NetworkManager crashes when trying to connect via 3g modem, leaves system messed up

[John Lenton]

Binary package hint: network-manager

Something in the NetworkManager / modem-manager conversation fails, and NetworkManager crashes, leaving pppd running but the modem in a really bad state, and the system very unstable.

Yeah, all the last is probably the kerne's fault (there's a bug for them on that), but I'm rather frustrated so let me vent, OK? Ok.

So! Here's what I think is relevant from /var/log/syslog:

Aug 10 19:58:14 molle kernel: [ 894.034524] option 2-1:1.2: GSM modem (1-port) converter detected
Aug 10 19:58:14 molle modem-manager: (ttyUSB0) opening serial device...
Aug 10 19:58:14 molle modem-manager: (ttyUSB0): probe requested by plugin 'Huawei'
Aug 10 19:58:14 molle modem-manager: (Huawei): (ttyUSB1) deferring support check
Aug 10 19:58:14 molle modem-manager: (Huawei): (ttyUSB2) deferring support check
Aug 10 19:58:17 molle modem-manager: (ttyUSB1): re-checking support...
Aug 10 19:58:17 molle modem-manager: (Huawei): (ttyUSB1) deferring support check
Aug 10 19:58:17 molle modem-manager: (ttyUSB2): re-checking support...
Aug 10 19:58:17 molle modem-manager: (Huawei): (ttyUSB2) deferring support check
Aug 10 19:58:19 molle wpa_supplicant[3260]: CTRL-EVENT-SCAN-RESULTS
Aug 10 19:58:19 molle modem-manager: (ttyUSB0) closing serial device...
Aug 10 19:58:19 molle modem-manager: (Huawei): GSM modem /sys/devices/pci0000:00/0000:00:1d.7/usb2/2-1 claimed port ttyUSB0
Aug 10 19:58:19 molle modem-manager: Added modem /sys/devices/pci0000:00/0000:00:1d.7/usb2/2-1
Aug 10 19:58:19 molle modem-manager: signal "completed" (from "Completed") exported but not found in object class "MMGenericGsm"
Aug 10 19:58:19 molle modem-manager: Exported modem /sys/devices/pci0000:00/0000:00:1d.7/usb2/2-1 as /org/freedesktop/ModemManager/Modems/0
Aug 10 19:58:19 molle NetworkManager: <info> (ttyUSB0): new GSM device (driver: 'option1')
Aug 10 19:58:19 molle NetworkManager: <info> (ttyUSB0): exported as /org/freedesktop/NetworkManager/Devices/2
Aug 10 19:58:19 molle NetworkManager: <info> (ttyUSB0): now managed
Aug 10 19:58:19 molle NetworkManager: <info> (ttyUSB0): device state change: 1 -> 2 (reason 2)
Aug 10 19:58:19 molle NetworkManager: <info> (ttyUSB0): deactivating device (reason: 2).
Aug 10 19:58:19 molle NetworkManager: flush_routes: assertion `iface_idx >= 0' failed
Aug 10 19:58:19 molle NetworkManager: flush_addresses: assertion `iface_idx >= 0' failed
Aug 10 19:58:19 molle NetworkManager: <info> (ttyUSB0): device state change: 2 -> 3 (reason 0)
Aug 10 19:58:20 molle modem-manager: (ttyUSB1): re-checking support...
Aug 10 19:58:20 molle modem-manager: (ttyUSB1) opening serial device...
Aug 10 19:58:20 molle modem-manager: (ttyUSB2): re-checking support...
Aug 10 19:58:20 molle modem-manager: (ttyUSB2) opening serial device...
Aug 10 19:58:20 molle modem-manager: (ttyUSB2) closing serial device...
Aug 10 19:58:20 molle modem-manager: (Huawei): GSM modem /sys/devices/pci0000:00/0000:00:1d.7/usb2/2-1 claimed port ttyUSB2
Aug 10 19:58:25 molle modem-manager: (ttyUSB1) closing serial device...
Aug 10 19:58:25 molle modem-manager: (ttyUSB1) opening serial device...
Aug 10 19:58:25 molle modem-manager: (ttyUSB1): probe requested by plugin 'Generic'
Aug 10 19:58:26 molle NetworkManager: <info> Activation (ttyUSB0) starting connection 'CTI'
Aug 10 19:58:26 molle NetworkManager: <info> (ttyUSB0): device state change: 3 -> 4 (reason 0)
Aug 10 19:58:26 molle NetworkManager: <info> Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) scheduled...
Aug 10 19:58:26 molle NetworkManager: <info> Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) started...
Aug 10 19:58:26 molle NetworkManager: <info> Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) complete.
Aug 10 19:58:26 molle modem-manager: (ttyUSB0) opening serial device...
Aug 10 19:58:27 molle modem-manager: Registration state changed: 1
Aug 10 19:58:27 molle NetworkManager: <info> Activation (ttyUSB0) Stage 2 of 5 (Device Configure) scheduled...
Aug 10 19:58:27 molle NetworkManager: <info> Activation (ttyUSB0) Stage 2 of 5 (Device Configure) starting...
Aug 10 19:58:27 molle NetworkManager: <info> (ttyUSB0): device state change: 4 -> 5 (reason 0)
Aug 10 19:58:27 molle NetworkManager: <info> Starting pppd connection
Aug 10 19:58:27 molle NetworkManager: <debug> [1249945107.311201] nm_ppp_manager_start(): Command line: /usr/sbin/pppd nodetach lock nodefaultroute user ctigprs ttyUSB0 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
Aug 10 19:58:27 molle NetworkManager: <debug> [1249945107.313719] nm_ppp_manager_start(): ppp started with pid 3928
Aug 10 19:58:27 molle NetworkManager: <info> Activation (ttyUSB0) Stage 2 of 5 (Device Configure) complete.
Aug 10 19:58:27 molle pppd[3928]: Plugin /usr/lib/pppd/2.4.4/nm-pppd-plugin.so loaded.
Aug 10 19:58:27 molle pppd[3928]: pppd 2.4.5 started by root, uid 0
Aug 10 19:58:27 molle pppd[3928]: Using interface ppp0
Aug 10 19:58:27 molle pppd[3928]: Connect: ppp0 <--> /dev/ttyUSB0
Aug 10 19:58:27 molle NetworkManager: SCPlugin-Ifupdown: devices added (path: /sys/devices/virtual/net/ppp0, iface: ppp0)
Aug 10 19:58:27 molle NetworkManager: <info> (ttyUSB0): device state change: 5 -> 6 (reason 0)
Aug 10 19:58:27 molle pppd[3928]: Unable to obtain CHAP password for ctigprs on UMTS_CHAP_SRVR from plugin
Aug 10 19:58:27 molle pppd[3928]: No CHAP secret found for authenticating us to UMTS_CHAP_SRVR
Aug 10 19:58:27 molle pppd[3928]: CHAP authentication succeeded
Aug 10 19:58:27 molle pppd[3928]: CHAP authentication succeeded
Aug 10 19:58:30 molle pppd[3928]: Could not determine remote IP address: defaulting to 10.64.64.64
Aug 10 19:58:30 molle pppd[3928]: Cannot determine ethernet address for proxy ARP
Aug 10 19:58:30 molle pppd[3928]: local IP address 186.13.204.237
Aug 10 19:58:30 molle pppd[3928]: remote IP address 10.64.64.64
Aug 10 19:58:30 molle pppd[3928]: primary DNS address 170.51.255.167
Aug 10 19:58:30 molle pppd[3928]: secondary DNS address 170.51.255.100
Aug 10 19:58:36 molle modem-manager: (ttyUSB1) closing serial device...

that line up there is the last line from NetworkManager.

Attached is the .crash file apport generated; unfortunately the system hung shortly after and it seems the report is corrupted, so I'm not able to process it with apport itself.

ProblemType: Bug
Architecture: i386
Date: Mon Aug 10 21:27:26 2009
DistroRelease: Ubuntu 9.10
NonfreeKernelModules: nvidia
Package: network-manager 0.8~a~git.20090804t185522.4bab334-0ubuntu1
ProcEnviron:
 LANGUAGE=en_GB.UTF-8
 PATH=(custom, user)
 LANG=en_GB.UTF-8
 SHELL=/bin/bash
ProcVersionSignature: Ubuntu 2.6.31-5.24-generic
SourcePackage: network-manager
Uname: Linux 2.6.31-5-generic i686
WpaSupplicantLog:

[Victor Vargas (kamus)]

Dear Jhon, can you try to upgrade your Karmic system (up to date), network-manager package and then check if this problem is still occurring?

[John Lenton (chipaca)]

On Thu, Sep 03, 2009 at 03:50:04PM -0000, Kamus wrote:
> Dear Jhon, can you try to upgrade your Karmic system (up to date),
> network-manager package and then check if this problem is still
> occurring?

How up-to-date? It happened again last night, with the system updated
yesterday morning.

[Victor Vargas (kamus)]

John, please launch nautilus and navigate to your /var/crash directory and double click on the crash report you wish to submit, and if you can attach a Backtrace for network-manager would be great! (you should see further information at https://wiki.ubuntu.com/DebuggingNetworkManager)

Regards

[John Lenton (chipaca)]

On Thu, Sep 03, 2009 at 05:06:53PM -0000, Kamus wrote:
> John, please launch nautilus and navigate to your /var/crash directory
> and double click on the crash report you wish to submit, and if you can
> attach a Backtrace for network-manager would be great! (you should see
> further information at https://wiki.ubuntu.com/DebuggingNetworkManager)

I get a dialog box saying

   The problem cannot be reported:

   The program crashed on an assertion failure, but the
   message could not be retrieved. Apport does not support
   reporting these crashes.

                                               [Close]

[David Kågedal (dkagedal)]

I started getting similar problems in karmic, but I haven't seen any nm crash. I just see messages like these in my syslog:

Oct 1 07:41:48 krank kernel: [ 2287.600633] usb 5-2: configuration #1 chosen from 1 choice
Oct 1 07:41:48 krank kernel: [ 2287.633422] option 5-2:1.0: GSM modem (1-port) converter detected
Oct 1 07:41:48 krank kernel: [ 2287.633518] usb 5-2: GSM modem (1-port) converter now attached to ttyUSB0
Oct 1 07:41:48 krank kernel: [ 2287.636380] option 5-2:1.1: GSM modem (1-port) converter detected
Oct 1 07:41:48 krank modem-manager: (Huawei): (ttyUSB1) deferring support check
Oct 1 07:41:48 krank modem-manager: (ttyUSB0) opening serial device...
Oct 1 07:41:48 krank modem-manager: (ttyUSB0) opening serial device...
Oct 1 07:41:51 krank modem-manager: (ttyUSB1): re-checking support...
Oct 1 07:41:51 krank modem-manager: (Huawei): (ttyUSB1) deferring support check
Oct 1 07:41:54 krank modem-manager: (ttyUSB1): re-checking support...
Oct 1 07:41:54 krank modem-manager: (Huawei): (ttyUSB1) deferring support check
Oct 1 07:41:57 krank modem-manager: (ttyUSB1): re-checking support...
Oct 1 07:41:57 krank modem-manager: (Huawei): (ttyUSB1) deferring support check
Oct 1 07:42:00 krank modem-manager: (ttyUSB1): re-checking support...
Oct 1 07:42:00 krank modem-manager: (Huawei): (ttyUSB1) deferring support check
Oct 1 07:42:03 krank modem-manager: (ttyUSB1): re-checking support...
Oct 1 07:42:03 krank modem-manager: (Huawei): (ttyUSB1) deferring support check
Oct 1 07:42:06 krank modem-manager: (ttyUSB1): re-checking support...
Oct 1 07:42:06 krank modem-manager: (Huawei): (ttyUSB1) deferring support check
Oct 1 07:42:09 krank modem-manager: (ttyUSB1): re-checking support...
Oct 1 07:42:09 krank modem-manager: (Huawei): (ttyUSB1) deferring support check
Oct 1 07:42:12 krank modem-manager: (ttyUSB1): re-checking support...

and so on

[Andrew Cowie (afcowie)]

In addition to periodic crashes (which *may* have subsided, can't be sure, but I haven't seen one in about 2 days), I get the loop described by David above quite a bit.

And, yet another variation, sometimes it connects, but then NetworkManager doesn't get around to writing any nameservers into the /etc/resolv.conf file. My workaround has been to tail -f /var/log/messages, and if I notice it getting that far to manually edit [ok, copy in a known good] resolv.conf with some DNS servers and on we go.

Most of the time, though, the only thing I can do to make my mobile broadband work is to reboot the machine. And that only works 50% of the time.

Ubuntu Karmic is hell because of all this. This device & NetworkManager [ie, this system dual booted] work fine on an up-to-date Gentoo Linux with a 2.6.30 kernel.

AfC

[sosostris (michael-wochs)]

Same Problem as David #6. The syslog shows an infinite loop of these 2 lines, though everything works fine.

Nov 21 17:31:27 home modem-manager: (ttyUSB0): re-checking support...
Nov 21 17:31:27 home modem-manager: (Huawei): (ttyUSB0) deferring support check
Nov 21 17:31:30 home modem-manager: (ttyUSB0): re-checking support...
Nov 21 17:31:30 home modem-manager: (Huawei): (ttyUSB0) deferring support check
Nov 21 17:31:33 home modem-manager: (ttyUSB0): re-checking support...
Nov 21 17:31:33 home modem-manager: (Huawei): (ttyUSB0) deferring support check
Nov 21 17:31:36 home modem-manager: (ttyUSB0): re-checking support...
Nov 21 17:31:36 home modem-manager: (Huawei): (ttyUSB0) deferring support check

[Michael Rüttgers (mruettgers)]

The problem resulting in the infinite loop of the lines mentioned above was fixed for me using the trunk builds of network-manager and modemmanager:
https://edge.launchpad.net/~network-manager/+archive/trunk

[Launchpad Janitor (janitor)]

[Expired for network-manager (Ubuntu) because there has been no activity for 60 days.]