Re: umts connection closed after succefull ppp negotiation

[Dan Williams <dcbw redhat com>]

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