Re: Problem with Simple.Connect

[Pablo Martí Gamboa <pmarti warp es>]

2009/10/7 Dan Williams <dcbw redhat com>

On Tue, 2009-10-06 at 12:43 +0200, Pablo Martí Gamboa wrote:
> Hi all,
>
> I'm getting a unreliable behavior with Simple.Connect, the first call
> will succeed, but further calls won't.
>
>
> Going through the logs with Tambet, we have noticed that there is
> something weird going on with IPv6 code:

I think that's mostly unrelated; NM will not finish the connection until
both IP4 and IP6 have completed, but of course in your case you don't
have IP6 configured since this is a mobile broadband connection, so that
stage is just a null-op.  The real problem seems to be:

Oct  6 10:27:04 lenovo NetworkManager: <WARN>  pppd_timed_out(): Looks
like pppd didn't initialize our dbus module

which indicates that PPP did not successfully complete, or that the NM
pppd plugin could not push the IP4 config information back to
NetworkManager.  Can you run NM like so:

NM_PPP_DEBUG=1 /usr/sbin/NetworkManager --no-daemon

see successful.log and error.log (first and second attempts respectively)
 

and then reproduce the issue?  That should show a lot more log output
(including pppd's stdout debugging info) that will allow us to figure
out what's going on here.

Also, did this just start happening, or has this been around for a bit?
Or did you just install something new?

I forgot to mention that this with NetworkManager + Wader rather than NM + MM. I'm testing the integration of both packages before (hopefully) the release of Ubuntu 9.10 final. I hadn't tested Simple.Connect in a while.

Thanks a lot for your time and help!!

Pablo

-- 
Pablo Martí
http://www.linkedin.com/in/pmarti || http://www.warp.es
python -c "print '706d6172746940776172702e6573'.decode('hex')"

NetworkManager: <info>  Activation (ttyUSB0) starting connection 'Vodafone'
NetworkManager: <info>  (ttyUSB0): device state change: 3 -> 4 (reason 0)
NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) scheduled...
NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) started...
NetworkManager: <info>  (ttyUSB0): device state change: 4 -> 6 (reason 0)
NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) complete.
NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) scheduled...
NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) started...
NetworkManager: <info>  (ttyUSB0): device state change: 6 -> 4 (reason 0)
NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) complete.
NetworkManager: <info>  Activation (ttyUSB0) Stage 2 of 5 (Device Configure) scheduled...
NetworkManager: <info>  Activation (ttyUSB0) Stage 2 of 5 (Device Configure) starting...
NetworkManager: <info>  (ttyUSB0): device state change: 4 -> 5 (reason 0)
NetworkManager: <info>  Activation (ttyUSB0) Stage 2 of 5 (Device Configure) successful.
NetworkManager: <info>  Activation (ttyUSB0) Stage 3 of 5 (IP Configure Start) scheduled.
NetworkManager: <info>  Activation (ttyUSB0) Stage 2 of 5 (Device Configure) complete.
NetworkManager: <info>  Activation (ttyUSB0) Stage 3 of 5 (IP Configure Start) started...
NetworkManager: <info>  (ttyUSB0): device state change: 5 -> 7 (reason 0)
NetworkManager: <info>  Starting pppd connection
NetworkManager: <debug> [1254985070.460266] nm_ppp_manager_start(): Command line: /usr/sbin/pppd nodetach lock nodefaultroute debug user vodafone ttyUSB0 noipdefault noauth usepeerdns lcp-echo-failure 0 lcp-echo-interval 0 ipparam /org/freedesktop/NetworkManager/PPP/2 plugin /usr/lib/pppd/2.4.4/nm-pppd-plugin.so
Plugin /usr/lib/pppd/2.4.4/nm-pppd-plugin.so loaded.
** Message: nm-ppp-plugin: (plugin_init): initializing
NetworkManager: <debug> [1254985070.468209] nm_ppp_manager_start(): ppp started with pid 3471
NetworkManager: <info>  Activation (ttyUSB0) Stage 4 of 5 (IP6 Configure Get) scheduled...
NetworkManager: <info>  Activation (ttyUSB0) Stage 3 of 5 (IP Configure Start) complete.
NetworkManager: <info>  Activation (ttyUSB0) Stage 4 of 5 (IP6 Configure Get) started...
NetworkManager: <info>  Activation (ttyUSB0) Stage 4 of 5 (IP6 Configure Get) complete.
** Message: nm-ppp-plugin: (nm_phasechange): status 3 / phase 'serial connection'
NetworkManager: <WARN>  pppd_timed_out(): Looks like pppd didn't initialize our dbus module
NetworkManager: <info>  (ttyUSB0): device state change: 7 -> 9 (reason 14)
NetworkManager: <info>  Marking connection 'Vodafone' invalid.
NetworkManager: Tried to set deprecated property gsm/puk
NetworkManager: <info>  Activation (ttyUSB0) failed.
NetworkManager: <info>  (ttyUSB0): device state change: 9 -> 3 (reason 0)
NetworkManager: <info>  (ttyUSB0): deactivating device (reason: 0).
NetworkManager: flush_routes: assertion `iface_idx >= 0' failed
NetworkManager: flush_addresses: assertion `iface_idx >= 0' failed
NetworkManager: <info>  Policy set 'Auto eth0' (eth0) as default for routing and DNS.
NetworkManager: <debug> [1254985093.001338] ensure_killed(): waiting for ppp pid 3471 to exit

NetworkManager: <info>  Activation (ttyUSB0) starting connection 'Vodafone'
NetworkManager: <info>  (ttyUSB0): device state change: 3 -> 4 (reason 0)
NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) scheduled...
NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) started...
NetworkManager: <info>  (ttyUSB0): device state change: 4 -> 6 (reason 0)
NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) complete.
NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) scheduled...
NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) started...
NetworkManager: <info>  (ttyUSB0): device state change: 6 -> 4 (reason 0)
NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) complete.
NetworkManager: <info>  Activation (ttyUSB0) Stage 2 of 5 (Device Configure) scheduled...
NetworkManager: <info>  Activation (ttyUSB0) Stage 2 of 5 (Device Configure) starting...
NetworkManager: <info>  (ttyUSB0): device state change: 4 -> 5 (reason 0)
NetworkManager: <info>  Activation (ttyUSB0) Stage 2 of 5 (Device Configure) successful.
NetworkManager: <info>  Activation (ttyUSB0) Stage 3 of 5 (IP Configure Start) scheduled.
NetworkManager: <info>  Activation (ttyUSB0) Stage 2 of 5 (Device Configure) complete.
NetworkManager: <info>  Activation (ttyUSB0) Stage 3 of 5 (IP Configure Start) started...
NetworkManager: <info>  (ttyUSB0): device state change: 5 -> 7 (reason 0)
NetworkManager: <info>  Starting pppd connection
NetworkManager: <debug> [1254985020.817535] nm_ppp_manager_start(): Command line: /usr/sbin/pppd nodetach lock nodefaultroute debug user vodafone ttyUSB0 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
NetworkManager: <debug> [1254985020.818679] nm_ppp_manager_start(): ppp started with pid 3360
NetworkManager: <info>  Activation (ttyUSB0) Stage 4 of 5 (IP6 Configure Get) scheduled...
NetworkManager: <info>  Activation (ttyUSB0) Stage 3 of 5 (IP Configure Start) complete.
NetworkManager: <info>  Activation (ttyUSB0) Stage 4 of 5 (IP6 Configure Get) started...
NetworkManager: <info>  Activation (ttyUSB0) Stage 4 of 5 (IP6 Configure Get) complete.
Plugin /usr/lib/pppd/2.4.4/nm-pppd-plugin.so loaded.
** Message: nm-ppp-plugin: (plugin_init): initializing
** Message: nm-ppp-plugin: (nm_phasechange): status 3 / phase 'serial connection'
using channel 1
Using interface ppp0
Connect: ppp0 <--> /dev/ttyUSB0
** Message: nm-ppp-plugin: (nm_phasechange): status 5 / phase 'establish'
sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x4f1346bc> <pcomp> <accomp>]
NetworkManager:    SCPlugin-Ifupdown: devices added (path: /sys/devices/virtual/net/ppp0, iface: ppp0)
NetworkManager:    SCPlugin-Ifupdown: device added (path: /sys/devices/virtual/net/ppp0, iface: ppp0): no ifupdown configuration found.
rcvd [LCP ConfReq id=0x0 <asyncmap 0x0> <auth chap MD5> <magic 0x1b3bb24> <pcomp> <accomp>]
sent [LCP ConfAck id=0x0 <asyncmap 0x0> <auth chap MD5> <magic 0x1b3bb24> <pcomp> <accomp>]
rcvd [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0x4f1346bc> <pcomp> <accomp>]
** Message: nm-ppp-plugin: (nm_phasechange): status 6 / phase 'authenticate'
rcvd [LCP DiscReq id=0x1 magic=0x1b3bb24]
rcvd [CHAP Challenge id=0x1 <3cf39c0074e82440923819378015d158>, name = "UMTS_CHAP_SRVR"]
** Message: nm-ppp-plugin: (get_credentials): passwd-hook, requesting credentials...
NetworkManager: Tried to set deprecated property gsm/puk
** Message: nm-ppp-plugin: (get_credentials): got credentials from NetworkManager
sent [CHAP Response id=0x1 <fe3493b049880774f03de9588b3aca26>, name = "vodafone"]
rcvd [CHAP Success id=0x1 ""]
CHAP authentication succeeded
CHAP authentication succeeded
** Message: nm-ppp-plugin: (nm_phasechange): status 8 / phase 'network'
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=0x2 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 ConfNak id=0x3 <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=0x4 <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=0x4 <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=0x5 <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=0x0]
sent [IPCP ConfNak id=0x0 <addr 0.0.0.0>]
rcvd [IPCP ConfRej id=0x5 <compress VJ 0f 01>]
sent [IPCP ConfReq id=0x6 <addr 0.0.0.0> <ms-dns1 10.11.12.13> <ms-dns2 10.11.12.14>]
rcvd [IPCP ConfReq id=0x1]
sent [IPCP ConfAck id=0x1]
rcvd [IPCP ConfNak id=0x6 <addr 77.210.32.210> <ms-dns1 212.73.32.3> <ms-dns2 212.73.32.67>]
sent [IPCP ConfReq id=0x7 <addr 77.210.32.210> <ms-dns1 212.73.32.3> <ms-dns2 212.73.32.67>]
rcvd [IPCP ConfAck id=0x7 <addr 77.210.32.210> <ms-dns1 212.73.32.3> <ms-dns2 212.73.32.67>]
Could not determine remote IP address: defaulting to 10.64.64.64
Cannot determine ethernet address for proxy ARP
local  IP address 77.210.32.210
remote IP address 10.64.64.64
primary   DNS address 212.73.32.3
secondary DNS address 212.73.32.67
** Message: nm-ppp-plugin: (nm_phasechange): status 9 / phase 'running'
** Message: nm-ppp-plugin: (nm_ip_up): ip-up event
** Message: nm-ppp-plugin: (nm_ip_up): sending Ip4Config to NetworkManager...
Script /etc/ppp/ip-up started (pid 3371)
NetworkManager: <info>  PPP manager(IP Config Get) reply received.
NetworkManager: <info>  Activation (ttyUSB0) Stage 4 of 5 (IP4 Configure Get) scheduled...
NetworkManager: <info>  Activation (ttyUSB0) Stage 4 of 5 (IP4 Configure Get) started...
NetworkManager: <info>  Activation (ttyUSB0) Stage 5 of 5 (IP Configure Commit) scheduled...
NetworkManager: <info>  Activation (ttyUSB0) Stage 4 of 5 (IP4 Configure Get) complete.
NetworkManager: <info>  Activation (ttyUSB0) Stage 5 of 5 (IP Configure Commit) started...
Script /etc/ppp/ip-up finished (pid 3371), status = 0x0
NetworkManager: <info>  Policy set 'Auto eth0' (eth0) as default for routing and DNS.
NetworkManager: <info>  (ttyUSB0): device state change: 7 -> 8 (reason 0)
NetworkManager: <info>  Activation (ttyUSB0) successful, device activated.
NetworkManager: <info>  Activation (ttyUSB0) Stage 5 of 5 (IP Configure Commit) complete.
NetworkManager: <info>  (ttyUSB0): device state change: 8 -> 3 (reason 39)
NetworkManager: <info>  (ttyUSB0): deactivating device (reason: 39).
NetworkManager: <info>  Policy set 'Auto eth0' (eth0) as default for routing and DNS.
Terminating on signal 15
** Message: nm-ppp-plugin: (nm_phasechange): status 10 / phase 'terminate'
** Message: nm-ppp-plugin: (nm_phasechange): status 8 / phase 'network'
Connect time 0.6 minutes.
Sent 0 bytes, received 52 bytes.
Script /etc/ppp/ip-down started (pid 3446)
** Message: nm-ppp-plugin: (nm_phasechange): status 5 / phase 'establish'
sent [LCP TermReq id=0x2 "User request"]
rcvd [LCP TermAck id=0x2]
** Message: nm-ppp-plugin: (nm_phasechange): status 11 / phase 'disconnect'
Connection terminated.
NetworkManager:    SCPlugin-Ifupdown: devices removed (path: /sys/devices/virtual/net/ppp0, iface: ppp0)
** Message: nm-ppp-plugin: (nm_phasechange): status 1 / phase 'dead'
Script /etc/ppp/ip-down finished (pid 3446), status = 0x0
** Message: nm-ppp-plugin: (nm_exit_notify): cleaning up
NetworkManager: <debug> [1254985062.000334] ensure_killed(): waiting for ppp pid 3360 to exit
NetworkManager: <debug> [1254985062.000466] ensure_killed(): ppp pid 3360 cleaned up