2009/10/7 Dan Williams <[email protected]> > 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
_______________________________________________ NetworkManager-list mailing list [email protected] http://mail.gnome.org/mailman/listinfo/networkmanager-list
