Re: Problem with Simple.Connect

[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

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?

Dan


> 
> ( http://pastebin.ca/1597233 )
> 
> 
> Oct  6 10:26:43 lenovo NetworkManager: <info>  (/dev/ttyUSB0): device
> state change: 4 -> 5 (reason 0)
> Oct  6 10:26:43 lenovo NetworkManager: <info>  Activation
> (/dev/ttyUSB0) Stage 2 of 5 (Device Configure) successful.
> Oct  6 10:26:43 lenovo NetworkManager: <info>  Activation
> (/dev/ttyUSB0) Stage 3 of 5 (IP Configure Start) scheduled.
> Oct  6 10:26:43 lenovo NetworkManager: <info>  Activation
> (/dev/ttyUSB0) Stage 2 of 5 (Device Configure) complete.
> Oct  6 10:26:43 lenovo NetworkManager: <info>  Activation
> (/dev/ttyUSB0) Stage 3 of 5 (IP Configure Start) started...
> Oct  6 10:26:43 lenovo NetworkManager: <info>  (/dev/ttyUSB0): device
> state change: 5 -> 7 (reason 0)
> Oct  6 10:26:43 lenovo NetworkManager: <info>  Starting pppd
> connection
> Oct  6 10:26:43 lenovo NetworkManager: <debug> [1254817603.714520]
> nm_ppp_manager_start(): Command line: /usr/sbin/pppd nodetach lock
> nodefaultroute /dev/ttyUSB0 noipdefault noauth usepeerdns
> lcp-echo-failure 0 lcp-echo-interval 0
> ipparam /org/freedesktop/NetworkManager/PPP/3
> plugin /usr/lib/pppd/2.4.4/nm-pppd-plugin.so
> Oct  6 10:26:43 lenovo NetworkManager: <debug> [1254817603.726521]
> nm_ppp_manager_start(): ppp started with pid 3625
> Oct  6 10:26:43 lenovo NetworkManager: <info>  Activation
> (/dev/ttyUSB0) Stage 4 of 5 (IP6 Configure Get) scheduled...
> Oct  6 10:26:43 lenovo NetworkManager: <info>  Activation
> (/dev/ttyUSB0) Stage 3 of 5 (IP Configure Start) complete.
> Oct  6 10:26:43 lenovo NetworkManager: <info>  Activation
> (/dev/ttyUSB0) Stage 4 of 5 (IP6 Configure Get) started...
> Oct  6 10:26:43 lenovo NetworkManager: <info>  Activation
> (/dev/ttyUSB0) Stage 4 of 5 (IP6 Configure Get) complete.
> Oct  6 10:26:51 lenovo wpa_supplicant[1228]: CTRL-EVENT-SCAN-RESULTS 
> Oct  6 10:27:04 lenovo NetworkManager: <WARN>  pppd_timed_out(): Looks
> like pppd didn't initialize our dbus module
> Oct  6 10:27:04 lenovo NetworkManager: <info>  (/dev/ttyUSB0): device
> state change: 7 -> 9 (reason 14)
> Oct  6 10:27:04 lenovo NetworkManager: <info>  Marking connection
> 'Vodafone (Airtel) connection' invalid.
> 
> 
> As you can see, it starts stage 4/5 IP6, then goes to 3/5 of IP. After
> that I get a pppd_timed_out because it times out. It seems there is
> something weird going related to IPv6.
> 
> 
> Tambet recommended me to create a simple test case that, issues a
> Connect.Simple call and then starts pppd manually without the ipparam
> argument. This results in a better reliability ( 5 successful
> connections in a row). Attached you can find the script.
> 
> 
> At this stage I'm quite lost, Tambet has mentioned that there was a
> "recent" ipv6 merge that could be related to it. Any hints / ideas
> about what to try?
> 
> 
> Best regards,
> 
> 
> -- 
> Pablo Martí
> http://www.linkedin.com/in/pmarti || http://www.warp.es
> python -c "print '706d6172746940776172702e6573'.decode('hex')"
> 
> 
> _______________________________________________
> NetworkManager-list mailing list
> NetworkManager-list gnome org
> http://mail.gnome.org/mailman/listinfo/networkmanager-list