Re: umts connection closed after succefull ppp negotiation
- From: Dan Williams <dcbw redhat com>
- To: Alessandro Bono <alessandro bono gmail com>
- Cc: networkmanager-list gnome org
- Subject: Re: umts connection closed after succefull ppp negotiation
- Date: Tue, 28 Apr 2009 13:58:45 -0400
On Tue, 2009-04-28 at 18:42 +0200, Alessandro Bono wrote:
> 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
What dbus version?
Dan
> [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
> > >
> > >
> >
[
Date Prev][
Date Next] [
Thread Prev][
Thread Next]
[
Thread Index]
[
Date Index]
[
Author Index]
