Re: umts connection closed after succefull ppp negotiation
- From: Alessandro Bono <alessandro bono gmail com>
- To: Dan Williams <dcbw redhat com>
- Cc: networkmanager-list gnome org
- Subject: Re: umts connection closed after succefull ppp negotiation
- Date: Tue, 28 Apr 2009 18:42:35 +0200
On Tue, 2009-04-28 at 11:46 -0400, Dan Williams wrote:
> On Mon, 2009-04-27 at 14:14 +0200, Alessandro Bono wrote:
> > Hi
> >
> > I'm testing my new umts connection but seems there are problem with NM
> > on my system
> > I tried with two different modem (onda et505up and onda mt503hsa) with
> > the same result
> > warning "pppd_timed_out(): Looks like pppd didn't initialize our dbus
> > module" not seems influence the result, it's possible to remove this
> > warning changing a dbus acl but without any difference
> > below full log of a connection with pppd debug enabled and some info of
> > my system
> >
> > any idea how to debug or workaround this problem?
>
> Stop NM, then as root:
>
> NM_PPP_DEBUG=1 /usr/sbin/NetworkManager --no-daemon
Hi Dan
I tried as you suggest but not found nothing interesting
just to be sure I tried with wvdial with this configuration
[Dialer Defaults]
Modem = /dev/ttyUSB2
Baud = 460800
Init1 = ATZ
Init2 = AT+CGDCONT=1,"IP","ibox.tim.it",,0,0
ISDN = 0
Modem Type = Analog Modem
Carrier Check = no
Phone = *99#
Username = ''
Password = ''
and connection works without problem
below a full log with NM_PPP_DEBUG (I tried with and without username
and password)
NetworkManager: <info> Activation (ttyUSB2) starting connection 'TIM'
NetworkManager: <info> (ttyUSB2): device state change: 3 -> 4
NetworkManager: <info> Activation (ttyUSB2) Stage 1 of 5 (Device
Prepare) scheduled...
NetworkManager: <info> Activation (ttyUSB2) Stage 1 of 5 (Device
Prepare) started...
NetworkManager: <debug> [1240936873.552324] nm_serial_device_open():
(ttyUSB2) opening device...
NetworkManager: <info> Activation (ttyUSB2) Stage 1 of 5 (Device
Prepare) complete.
NetworkManager: <info> (ttyUSB2): powering
up...
NetworkManager: <info> Registered on Home
network
NetworkManager: <info> Associated with network: +COPS: 0,0,"Telecom
Italia Mobile",2
NetworkManager: <info> Connected,
Woo!
NetworkManager: <info> Activation (ttyUSB2) Stage 2 of 5 (Device
Configure) scheduled...
NetworkManager: <info> Activation (ttyUSB2) Stage 2 of 5 (Device
Configure) starting...
NetworkManager: <info> (ttyUSB2): device state change: 4 ->
5
NetworkManager: <info> Starting pppd
connection
NetworkManager: <debug> [1240936875.322454] nm_ppp_manager_start():
Command line: /usr/sbin/pppd nodetach lock nodefaultroute debug ttyUSB2
noipdefault noauth usepeerdns lcp-echo-failure 0 lcp-echo-interval 0
ipparam /org/freedesktop/NetworkManager/PPP/1
plugin /usr/lib/pppd/2.4.4/nm-pppd-plugin.so
Plugin /usr/lib/pppd/2.4.4/nm-pppd-plugin.so
loaded.
NetworkManager: <debug> [1240936875.342187] nm_ppp_manager_start(): ppp
started with pid
7319
NetworkManager: <info> Activation (ttyUSB2) Stage 2 of 5 (Device
Configure)
complete.
using channel
2
Using interface
ppp0
Connect: ppp0
<--> /dev/ttyUSB2
sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x2874a5b2> <pcomp>
<accomp>]
rcvd [LCP ConfReq id=0x3 <asyncmap 0x0> <auth chap MD5> <magic
0x117ef87> <pcomp> <accomp>]
sent [LCP ConfAck id=0x3 <asyncmap 0x0> <auth chap MD5> <magic
0x117ef87> <pcomp> <accomp>]
rcvd [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0x2874a5b2> <pcomp>
<accomp>]
rcvd [LCP DiscReq id=0x4 magic=0x117ef87]
rcvd [CHAP Challenge id=0x1 <3824bee55e4e3c26ee103d41b89a2210>, name =
"UMTS_CHAP_SRVR"]
** (process:7319): WARNING **: Could not get secrets: Rejected send
message, 7 matched rules; type="method_call", sender=":1.72" (uid=0
pid=7319 comm="/usr/sbin/pppd nodetach lock nodefaultroute debug ")
interface="org.freedesktop.NetworkManager.PPP" member="NeedSecrets"
error name="(unset)" requested_reply=0
destination="org.freedesktop.NetworkManager" (uid=0 pid=5936
comm="/usr/sbin/NetworkManager --no-daemon "))
Unable to obtain CHAP password for champagne on UMTS_CHAP_SRVR from
plugin
No CHAP secret found for authenticating us to UMTS_CHAP_SRVR
sent [CHAP Response id=0x1 <ca8c2baa0c5a38f79113f9736cbdc716>, name =
"champagne"]
rcvd [CHAP Success id=0x1 ""]
CHAP authentication succeeded
CHAP authentication succeeded
sent [CCP ConfReq id=0x1 <deflate 15> <deflate(old#) 15> <bsd v1 15>]
sent [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>]
rcvd [LCP ProtRej id=0x5 80 fd 01 01 00 0f 1a 04 78 00 18 04 78 00 15 03
2f]
Protocol-Reject for 'Compression Control Protocol' (0x80fd) received
rcvd [IPCP ConfNak id=0x1 <ms-dns1 10.11.12.13> <ms-dns2 10.11.12.14>
<ms-wins 10.11.12.13> <ms-wins 10.11.12.14>]
sent [IPCP ConfReq id=0x2 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1
10.11.12.13> <ms-dns2 10.11.12.14>]
rcvd [IPCP ConfNak id=0x2 <ms-dns1 10.11.12.13> <ms-dns2 10.11.12.14>
<ms-wins 10.11.12.13> <ms-wins 10.11.12.14>]
sent [IPCP ConfReq id=0x3 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1
10.11.12.13> <ms-dns2 10.11.12.14>]
rcvd [IPCP ConfReq id=0x2]
sent [IPCP ConfNak id=0x2 <addr 0.0.0.0>]
rcvd [IPCP ConfRej id=0x3 <compress VJ 0f 01>]
sent [IPCP ConfReq id=0x4 <addr 0.0.0.0> <ms-dns1 10.11.12.13> <ms-dns2
10.11.12.14>]
rcvd [IPCP ConfReq id=0x3]
sent [IPCP ConfAck id=0x3]
rcvd [IPCP ConfNak id=0x4 <addr 217.202.217.135> <ms-dns1
213.230.128.222> <ms-dns2 213.230.129.94>]
sent [IPCP ConfReq id=0x5 <addr 217.202.217.135> <ms-dns1
213.230.128.222> <ms-dns2 213.230.129.94>]
rcvd [IPCP ConfAck id=0x5 <addr 217.202.217.135> <ms-dns1
213.230.128.222> <ms-dns2 213.230.129.94>]
Could not determine remote IP address: defaulting to 10.64.64.64
Cannot determine ethernet address for proxy ARP
local IP address 217.202.217.135
remote IP address 10.64.64.64
primary DNS address 213.230.128.222
secondary DNS address 213.230.129.94
Script /etc/ppp/ip-up started (pid 7324)
Script /etc/ppp/ip-up finished (pid 7324), status = 0x0
NetworkManager: <WARN> pppd_timed_out(): Looks like pppd didn't
initialize our dbus module
NetworkManager: <info> (ttyUSB2): device state change: 5 -> 9
Terminating on signal 15
NetworkManager: <debug> [1240936891.003005] nm_serial_device_close():
Closing device 'ttyUSB2'
Connect time 0.3 minutes.
Sent 0 bytes, received 144 bytes.
NetworkManager: <info> Marking connection 'TIM' invalid.
NetworkManager: <info> Activation (ttyUSB2) failed.
NetworkManager: <info> (ttyUSB2): device state change: 9 -> 3
NetworkManager: <info> (ttyUSB2): deactivating device (reason: 0).
NetworkManager: nm_system_device_flush_ip4_routes_with_iface: assertion
`iface_idx >= 0' failed
NetworkManager: nm_system_device_flush_ip4_addresses_with_iface:
assertion `iface_idx >= 0' failed
Script /etc/ppp/ip-down started (pid 7400)
sent [LCP TermReq id=0x2 "User request"]
rcvd [LCP TermAck id=0x2]
Connection terminated.
Script /etc/ppp/ip-down finished (pid 7400), status = 0x0
NetworkManager: <debug> [1240936893.001609] ensure_killed(): waiting for
ppp pid 7319 to exit
NetworkManager: <debug> [1240936893.001772] ensure_killed(): ppp pid
7319 cleaned up
>
> and lets see what PPP thinks. You probably also want to try setting a
> username and password explicitly, which some devices seem to really
> want.
>
> Dan
>
> > thanks
> >
> > ps please cc to me, I'm not subscribed to ml
> >
> > distribution ubuntu jaunty 64bit
> >
> > dpkg -l | grep network-manager
> > ii network-manager
> > 0.7.1~rc4.1.cf199a964-0ubuntu2 network
> > management framework daemon
> > ii network-manager-gnome 0.7.1~rc4.1-0ubuntu2
> > network management framework (GNOME frontend
> > ii network-manager-openvpn 0.7.1~rc4.1.20090323
> > +bzr27-0ubuntu2 network management framework
> > (OpenVPN plugin
> > ii network-manager-pptp 0.7.1~rc4.20090316
> > +bzr23-0ubuntu3 network management framework
> > (PPTP plugin)
> > ii network-manager-vpnc 0.7.1~rc4.20090316
> > +bzr21-0ubuntu2 network management framework
> > (VPNC plugin)
> >
> > dpkg -l | grep ppp
> > ii ppp
> > 2.4.5~git20081126t100229-0ubuntu2
> > Point-to-Point Protocol (PPP) - daemon
> >
> >
> > Apr 27 14:05:08 champagne NetworkManager: <info> Activation (ttyUSB2)
> > starting connection
> > 'TIM'
> > Apr 27 14:05:08 champagne NetworkManager: <info> (ttyUSB2): device
> > state change: 3 ->
> > 4
> > Apr 27 14:05:08 champagne NetworkManager: <info> Activation (ttyUSB2)
> > Stage 1 of 5 (Device Prepare)
> > scheduled...
> > Apr 27 14:05:08 champagne NetworkManager: <info> Activation (ttyUSB2)
> > Stage 1 of 5 (Device Prepare)
> > started...
> > Apr 27 14:05:08 champagne NetworkManager: <debug> [1240833908.133093]
> > nm_serial_device_open(): (ttyUSB2) opening
> > device...
> > Apr 27 14:05:08 champagne NetworkManager: <info> Activation (ttyUSB2)
> > Stage 1 of 5 (Device Prepare)
> > complete.
> > Apr 27 14:05:08 champagne NetworkManager: <info> (ttyUSB2): powering
> > up...
> > Apr 27 14:05:08 champagne NetworkManager: <info> Registered on Home
> > network
> > Apr 27 14:05:08 champagne NetworkManager: <info> Associated with
> > network: +COPS: 0,0,"Telecom Italia
> > Mobile",0
> > Apr 27 14:05:08 champagne NetworkManager: <info> Connected,
> > Woo!
> > Apr 27 14:05:08 champagne NetworkManager: <info> Activation (ttyUSB2)
> > Stage 2 of 5 (Device Configure)
> > scheduled...
> > Apr 27 14:05:08 champagne NetworkManager: <info> Activation (ttyUSB2)
> > Stage 2 of 5 (Device Configure)
> > starting...
> > Apr 27 14:05:08 champagne NetworkManager: <info> (ttyUSB2): device
> > state change: 4 ->
> > 5
> > Apr 27 14:05:08 champagne NetworkManager: <info> Starting pppd
> > connection
> > Apr 27 14:05:08 champagne NetworkManager: <debug> [1240833908.566302]
> > nm_ppp_manager_start(): Command line: /usr/sbin/pppd nodetach lock
> > nodefaultroute ttyUSB2 noipdefault noauth usepeerdns lcp-echo-failure 0
> > lcp-echo-interval 0 ipparam /org/freedesktop/NetworkManager/PPP/0
> > plugin /usr/lib/pppd/2.4.4/nm-pppd-plugin.so
> > Apr 27 14:05:08 champagne NetworkManager: <debug> [1240833908.577009]
> > nm_ppp_manager_start(): ppp started with pid
> > 17545
> > Apr 27 14:05:08 champagne NetworkManager: <info> Activation (ttyUSB2)
> > Stage 2 of 5 (Device Configure)
> > complete.
> > Apr 27 14:05:08 champagne pppd[17545]:
> > Plugin /usr/lib/pppd/2.4.4/nm-pppd-plugin.so
> > loaded.
> > Apr 27 14:05:08 champagne pppd[17545]: pppd 2.4.5 started by root, uid
> > 0
> > Apr 27 14:05:08 champagne pppd[17545]: using channel
> > 6
> > Apr 27 14:05:08 champagne pppd[17545]: Using interface
> > ppp0
> > Apr 27 14:05:08 champagne pppd[17545]: Connect: ppp0
> > <--> /dev/ttyUSB2
> > Apr 27 14:05:08 champagne pppd[17545]: sent [LCP ConfReq id=0x1
> > <asyncmap 0x0> <magic 0x69f9c20a> <pcomp>
> > <accomp>]
> > Apr 27 14:05:08 champagne pppd[17545]: rcvd [LCP ConfReq id=0x3
> > <asyncmap 0x0> <auth chap MD5> <magic 0x143273a> <pcomp>
> > <accomp>]
> > Apr 27 14:05:08 champagne pppd[17545]: sent [LCP ConfAck id=0x3
> > <asyncmap 0x0> <auth chap MD5> <magic 0x143273a> <pcomp>
> > <accomp>]
> > Apr 27 14:05:08 champagne pppd[17545]: rcvd [LCP ConfAck id=0x1
> > <asyncmap 0x0> <magic 0x69f9c20a> <pcomp>
> > <accomp>]
> > Apr 27 14:05:08 champagne pppd[17545]: rcvd [LCP DiscReq id=0x4
> > magic=0x143273a]
> > Apr 27 14:05:08 champagne pppd[17545]: rcvd [CHAP Challenge id=0x1
> > <185744973e36b20764240745a244e6d7>, name =
> > "UMTS_CHAP_SRVR"]
> > Apr 27 14:05:08 champagne pppd[17545]: Unable to obtain CHAP password
> > for champagne on UMTS_CHAP_SRVR from
> > plugin
> > Apr 27 14:05:08 champagne pppd[17545]: No CHAP secret found for
> > authenticating us to
> > UMTS_CHAP_SRVR
> > Apr 27 14:05:08 champagne pppd[17545]: sent [CHAP Response id=0x1
> > <1c5af77c60e557b78d5037f01e6b393e>, name =
> > "champagne"]
> > Apr 27 14:05:08 champagne pppd[17545]: rcvd [CHAP Success id=0x1
> > ""]
> > Apr 27 14:05:08 champagne pppd[17545]: CHAP authentication
> > succeeded
> > Apr 27 14:05:08 champagne pppd[17545]: CHAP authentication
> > succeeded
> > Apr 27 14:05:08 champagne pppd[17545]: sent [CCP ConfReq id=0x1 <deflate
> > 15> <deflate(old#) 15> <bsd v1 15>]
> > Apr 27 14:05:08 champagne pppd[17545]: sent [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 27 14:05:08 champagne pppd[17545]: rcvd [LCP ProtRej id=0x5 80 fd 01
> > 01 00 0f 1a 04 78 00 18 04 78 00 15 03 2f]
> > Apr 27 14:05:08 champagne pppd[17545]: Protocol-Reject for 'Compression
> > Control Protocol' (0x80fd) received
> > Apr 27 14:05:09 champagne pppd[17545]: rcvd [IPCP ConfReq id=0x2]
> > Apr 27 14:05:09 champagne pppd[17545]: sent [IPCP ConfNak id=0x2 <addr
> > 0.0.0.0>]
> > Apr 27 14:05:09 champagne pppd[17545]: rcvd [IPCP ConfRej id=0x1
> > <compress VJ 0f 01>]
> > Apr 27 14:05:09 champagne pppd[17545]: sent [IPCP ConfReq id=0x2 <addr
> > 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
> > Apr 27 14:05:09 champagne pppd[17545]: rcvd [IPCP ConfReq id=0x3]
> > Apr 27 14:05:09 champagne pppd[17545]: sent [IPCP ConfAck id=0x3]
> > Apr 27 14:05:09 champagne pppd[17545]: rcvd [IPCP ConfNak id=0x2 <addr
> > 217.202.5.135> <ms-dns1 213.230.129.94> <ms-dns2 213.230.128.222>]
> > Apr 27 14:05:09 champagne pppd[17545]: sent [IPCP ConfReq id=0x3 <addr
> > 217.202.5.135> <ms-dns1 213.230.129.94> <ms-dns2 213.230.128.222>]
> > Apr 27 14:05:09 champagne pppd[17545]: rcvd [IPCP ConfAck id=0x3 <addr
> > 217.202.5.135> <ms-dns1 213.230.129.94> <ms-dns2 213.230.128.222>]
> > Apr 27 14:05:09 champagne pppd[17545]: Could not determine remote IP
> > address: defaulting to 10.64.64.64
> > Apr 27 14:05:09 champagne pppd[17545]: Cannot determine ethernet address
> > for proxy ARP
> > Apr 27 14:05:09 champagne pppd[17545]: local IP address 217.202.5.135
> > Apr 27 14:05:09 champagne pppd[17545]: remote IP address 10.64.64.64
> > Apr 27 14:05:09 champagne pppd[17545]: primary DNS address
> > 213.230.129.94
> > Apr 27 14:05:09 champagne pppd[17545]: secondary DNS address
> > 213.230.128.222
> > Apr 27 14:05:09 champagne pppd[17545]: Script /etc/ppp/ip-up started
> > (pid 17550)
> > Apr 27 14:05:13 champagne postfix/master[3803]: reload
> > configuration /etc/postfix
> > Apr 27 14:05:13 champagne pppd[17545]: Script /etc/ppp/ip-up finished
> > (pid 17550), status = 0x0
> > Apr 27 14:05:24 champagne NetworkManager: <WARN> pppd_timed_out():
> > Looks like pppd didn't initialize our dbus module
> > Apr 27 14:05:24 champagne NetworkManager: <info> (ttyUSB2): device
> > state change: 5 -> 9
> > Apr 27 14:05:24 champagne NetworkManager: <debug> [1240833924.005739]
> > nm_serial_device_close(): Closing device 'ttyUSB2'
> > Apr 27 14:05:24 champagne pppd[17545]: Terminating on signal 15
> > Apr 27 14:05:24 champagne pppd[17545]: Connect time 0.3 minutes.
> > Apr 27 14:05:24 champagne pppd[17545]: Sent 0 bytes, received 721 bytes.
> > Apr 27 14:05:24 champagne NetworkManager: <info> Marking connection
> > 'TIM' invalid.
> > Apr 27 14:05:24 champagne NetworkManager: <info> Activation (ttyUSB2)
> > failed.
> > Apr 27 14:05:24 champagne NetworkManager: <info> (ttyUSB2): device
> > state change: 9 -> 3
> > Apr 27 14:05:24 champagne NetworkManager: <info> (ttyUSB2):
> > deactivating device (reason: 0).
> > Apr 27 14:05:24 champagne dnsmasq[3777]: reading /etc/resolv.conf
> > Apr 27 14:05:24 champagne dnsmasq[3777]: using nameserver
> > 192.168.0.11#53
> > Apr 27 14:05:24 champagne dnsmasq[3777]: using nameserver
> > 213.230.128.222#53
> > Apr 27 14:05:24 champagne dnsmasq[3777]: using nameserver
> > 213.230.129.94#53
> > Apr 27 14:05:24 champagne NetworkManager: <info> (eth0): writing
> > resolv.conf to /sbin/resolvconf
> > Apr 27 14:05:24 champagne pppd[17545]: Script /etc/ppp/ip-down started
> > (pid 17626)
> > Apr 27 14:05:24 champagne pppd[17545]: sent [LCP TermReq id=0x2 "User
> > request"]
> > Apr 27 14:05:24 champagne pppd[17545]: rcvd [LCP TermAck id=0x2]
> > Apr 27 14:05:24 champagne NetworkManager: <info> Policy set 'Auto
> > eth0' (eth0) as default for routing and DNS.
> > Apr 27 14:05:24 champagne NetworkManager:
> > nm_system_device_flush_ip4_routes_with_iface: assertion `iface_idx >= 0'
> > failed
> > Apr 27 14:05:24 champagne NetworkManager:
> > nm_system_device_flush_ip4_addresses_with_iface: assertion `iface_idx >=
> > 0' failed
> > Apr 27 14:05:24 champagne pppd[17545]: Connection terminated.
> > Apr 27 14:05:24 champagne postfix/master[3803]: reload
> > configuration /etc/postfix
> > Apr 27 14:05:24 champagne pppd[17545]: Script /etc/ppp/ip-down finished
> > (pid 17626), status = 0x0
> > Apr 27 14:05:24 champagne pppd[17545]: Exit.
> > Apr 27 14:05:26 champagne NetworkManager: <debug> [1240833926.002163]
> > ensure_killed(): waiting for ppp pid 17545 to exit
> > Apr 27 14:05:26 champagne NetworkManager: <debug> [1240833926.002312]
> > ensure_killed(): ppp pid 17545 cleaned up
> >
> >
>
--
Cordiali Saluti
Alessandro Bono
[
Date Prev][
Date Next] [
Thread Prev][
Thread Next]
[
Thread Index]
[
Date Index]
[
Author Index]
