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 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 > > _______________________________________________ NetworkManager-list mailing list NetworkManager-list@gnome.org http://mail.gnome.org/mailman/listinfo/networkmanager-list