ModemManager fails to connect to Mobile (GSM). The mobile phone Nokia N900 (PR3) plugged via USB. Trying to connect (nm-applet) to configured Mobile network fails. Sometimes it happens to connect if 1. Nokia N900 is already connected via USB 2. NetworkManager is started. 3. From console executed # killall -TERM modem-manager 4. Maybe step three repeated several times... 5. From NM-Applet select Mobile connection of Provider and click. Reproducible: Always Steps to Reproduce: 1. NetworkManager is started normally 2. Connect Nokia N900, select PC Suite as type of connection 3. From nm-applet try to connect Actual Results: Fails to initiate connection via GSM modem (Nokia N900) Expected Results: Successful connection Please see attached files. connection failed (default behavior) : NM_Debug.txt MM_Debug.txt connection done when manually killed modem-manager from console while GSM modem is already connected via USB. uname -a Linux 8doch7121ha38 2.6.36-gentoo-r5 #1 SMP PREEMPT Wed Dec 15 17:48:37 TMT 2010 x86_64 Genuine Intel(R) CPU U4100 @ 1.30GHz GenuineIntel GNU/Linux Installed version of MM: net-misc/modemmanager 0.4_p20101211 with USE flag policykit [I] net-misc/networkmanager (0.8.2-r1@12/14/10): Network configuration and management in an easy way. Desktop environment independent. [I] net-misc/networkmanager-openvpn (0.8.2@12/15/10): NetworkManager OpenVPN plugin. [I] net-misc/networkmanager-pptp (0.8.2@12/15/10): NetworkManager PPTP plugin [I] net-misc/networkmanager-vpnc (0.8.2@12/14/10): NetworkManager VPNC plugin [I] net-misc/cnetworkmanager (0.21.1@12/15/10): Command line interface for NetworkManager. emerge --info Portage 2.1.9.25 (default/linux/amd64/10.0, gcc-4.4.5, glibc-2.12.1-r3, 2.6.36-gentoo-r5 x86_64) ================================================================= System uname: Linux-2.6.36-gentoo-r5-x86_64-Genuine_Intel-R-_CPU_U4100_@_1.30GHz-with-gentoo-2.0.1 Timestamp of tree: Wed, 15 Dec 2010 09:30:01 +0000 ccache version 3.1.3 [enabled] app-shells/bash: 4.1_p7 dev-java/java-config: 2.1.11-r1 dev-lang/python: 2.6.6-r1, 2.7.1, 3.1.3 dev-util/ccache: 3.1.3 dev-util/cmake: 2.8.1-r2 sys-apps/baselayout: 2.0.1-r1 sys-apps/openrc: 0.6.8 sys-apps/sandbox: 2.4 sys-devel/autoconf: 2.13, 2.65-r1 sys-devel/automake: 1.7.9-r1, 1.9.6-r3, 1.10.3, 1.11.1 sys-devel/binutils: 2.21 sys-devel/gcc: 4.3.5, 4.4.5, 4.5.1-r1 sys-devel/gcc-config: 1.4.1 sys-devel/libtool: 2.2.10 sys-devel/make: 3.81-r2 virtual/os-headers: 2.6.36.1 (sys-kernel/linux-headers) ACCEPT_KEYWORDS="amd64" ACCEPT_LICENSE="*" CBUILD="x86_64-pc-linux-gnu" CFLAGS="-O2 -pipe -march=core2" CHOST="x86_64-pc-linux-gnu" CONFIG_PROTECT="/etc /etc/X11/xorg.conf /etc/acpi/default.sh /etc/conf.d /etc/hibernate/common.conf /etc/wpa_supplicant /usr/share/applications/gnomecc.desktop /usr/share/openvpn/easy-rsa /var/bind" CONFIG_PROTECT_MASK="/etc/ca-certificates.conf /etc/env.d /etc/env.d/java/ /etc/fonts/fonts.conf /etc/gconf /etc/gentoo-release /etc/hwclock /etc/init.d /etc/revdep-rebuild /etc/sandbox.d /etc/splash /etc/terminfo" CXXFLAGS="-O2 -pipe -march=core2" DISTDIR="/usr/portage/distfiles" FEATURES="assume-digests binpkg-logs candy ccache distlocks fixlafiles fixpackages metadata-transfer news parallel-fetch protect-owned sandbox sfperms strict unknown-features-warn unmerge-logs unmerge-orphans" GENTOO_MIRRORS="http://distfiles.gentoo.org" LDFLAGS="-Wl,-O1 -Wl,--as-needed" LINGUAS="ru en de" MAKEOPTS="-j5" PKGDIR="/usr/portage/packages" PORTAGE_CONFIGROOT="/" PORTAGE_RSYNC_OPTS="--recursive --links --safe-links --perms --times --compress --force --whole-file --delete --stats --timeout=180 --exclude=/distfiles --exclude=/local --exclude=/packages" PORTAGE_TMPDIR="/var/tmp" PORTDIR="/usr/portage" PORTDIR_OVERLAY="/usr/local/portage/layman/sunrise /usr/local/portage/layman/zugaina /usr/local/portage/layman/pure-funtoo /usr/local/portage/layman/hron /usr/local/portage/layman/gnome /var/lib/layman/vmware" SYNC="rsync://rsync.gentoo.org/gentoo-portage" USE="7zip X aac acc acl acpi alsa amd64 ape automount avi battery berkdb bzip bzip2 cairo caps cddb cleartype cli cpudetection cpufreq cracklib crypt cxx dbus dhcpcd disk-partition divx dri dts dvb dvd dvdr encode equalizer extensions extras fam ffmpeg firefox flac fortran ftp gdbm gdm gif glitz gnome gnutls gpm gstreamer gtk gzip icecat iconv inotify iproute2 jpeg jpeg2k laptop layman lcms libnotify libsamplerate lzma lzo mktemp mmx modules mp3 mpeg mudflap multilib nautilus ncurses nls nptl nptlonly ntp ntpl ogg opengl openmp oss pam passwdqc pcmcia pcre pdf perl plugins pmu png portage pppd python quicktime radio rar readline sasl saveconfig sdl session smp sndfile sox spell sqlite sqlite3 sse sse2 ssh ssl ssse3 startup-notification svg sysfs tcpd threads thunderbird tiff tools udev unicode urandom usb uselocales v4l2 vim vim-syntax vorbis wavpack wmf xattr xcb xorg xulrunner xvid xvmc zlib" ALSA_CARDS="hda-intel" ALSA_PCM_PLUGINS="adpcm alaw asym copy dmix dshare dsnoop empty extplug file hooks iec958 ioplug ladspa lfloat linear meter mmap_emul mulaw multi null plug rate route share shm softvol" APACHE2_MODULES="actions alias auth_basic authn_alias authn_anon authn_dbm authn_default authn_file authz_dbm authz_default authz_groupfile authz_host authz_owner authz_user autoindex cache cgi cgid dav dav_fs dav_lock deflate dir disk_cache env expires ext_filter file_cache filter headers include info log_config logio mem_cache mime mime_magic negotiation rewrite setenvif speling status unique_id userdir usertrack vhost_alias" COLLECTD_PLUGINS="df interface irq load memory rrdtool swap syslog" ELIBC="glibc" GPSD_PROTOCOLS="ashtech aivdm earthmate evermore fv18 garmin garmintxt gpsclock itrax mtk3301 nmea ntrip navcom oceanserver oldstyle oncore rtcm104v2 rtcm104v3 sirf superstar2 timing tsip tripmate tnt ubx" INPUT_DEVICES="keyboard mouse joystick synaptics video_cards_intel evdev" KERNEL="linux" LCD_DEVICES="bayrad cfontz cfontz633 glk hd44780 lb216 lcdm001 mtxorb ncurses text" LINGUAS="ru en de" LIRC_DEVICES="devinput" PHP_TARGETS="php5-2" QEMU_SOFTMMU_TARGETS="i386 x86_64" QEMU_USER_TARGETS="i386 x86_64" RUBY_TARGETS="ruby18" USERLAND="GNU" VIDEO_CARDS="intel" XTABLES_ADDONS="quota2 psd pknock lscan length2 ipv4options ipset ipp2p iface geoip fuzzy condition tee tarpit sysrq steal rawnat logmark ipmark dhcpmac delude chaos account" Unset: CPPFLAGS, CTARGET, EMERGE_DEFAULT_OPTS, FFLAGS, INSTALL_MASK, LANG, LC_ALL, PORTAGE_BUNZIP2_COMMAND, PORTAGE_COMPRESS, PORTAGE_COMPRESS_FLAGS, PORTAGE_RSYNC_EXTRA_OPTS
Created attachment 257276 [details] ModemManager Debug
Created attachment 257278 [details] NetworkManager Debug
Created attachment 257279 [details] Debug to /var/log/messages This is a case when MM's managed to connect...
Created attachment 257281 [details] In case kernel config is required...
With version 0.4 there was a problem with n900 as it requires a bit longer to esteblish connection. Patch to fix it was backported to 0.4_p20101211. With this version I can no longer re-produce this behavior. piasekr@rob $ sudo lsusb Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub Bus 002 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub Bus 001 Device 002: ID 8087:0020 Intel Corp. Integrated Rate Matching Hub Bus 002 Device 002: ID 8087:0020 Intel Corp. Integrated Rate Matching Hub Bus 002 Device 003: ID 046d:c043 Logitech, Inc. MX320/MX400 Laser Mouse Bus 002 Device 004: ID 413c:2003 Dell Computer Corp. Keyboard Bus 001 Device 003: ID 0421:01c8 Nokia Mobile Phones N900 (PC-Suite Mode) Dec 17 15:58:31 [NetworkManager] <info> Activation (ttyACM0) starting connection '3 - Handsets'_ Dec 17 15:58:31 [NetworkManager] <info> (ttyACM0): device state change: 3 -> 4 (reason 0)_ Dec 17 15:58:31 [NetworkManager] <info> Activation (ttyACM0) Stage 1 of 5 (Device Prepare) scheduled..._ Dec 17 15:58:31 [NetworkManager] <info> Activation (ttyACM0) Stage 1 of 5 (Device Prepare) started..._ Dec 17 15:58:31 [NetworkManager] <info> Activation (ttyACM0) Stage 1 of 5 (Device Prepare) complete._ Dec 17 15:58:31 [modem-manager] (ttyACM0) opening serial device... Dec 17 15:58:31 [modem-manager] Modem /org/freedesktop/ModemManager/Modems/0: state changed (disabled -> enabling) Dec 17 15:58:32 [modem-manager] Modem /org/freedesktop/ModemManager/Modems/0: state changed (enabling -> enabled) Dec 17 15:58:32 [NetworkManager] <info> WWAN now enabled by radio killswitch_ Dec 17 15:58:32 [modem-manager] Modem /org/freedesktop/ModemManager/Modems/0: state changed (enabled -> registered) Dec 17 15:58:32 [modem-manager] Modem /org/freedesktop/ModemManager/Modems/0: state changed (registered -> connecting) Dec 17 15:58:34 [modem-manager] Modem /org/freedesktop/ModemManager/Modems/0: state changed (connecting -> connected) Dec 17 15:58:34 [NetworkManager] <info> Activation (ttyACM0) Stage 2 of 5 (Device Configure) scheduled..._ Dec 17 15:58:34 [NetworkManager] <info> Activation (ttyACM0) Stage 2 of 5 (Device Configure) starting..._ Dec 17 15:58:34 [NetworkManager] <info> (ttyACM0): device state change: 4 -> 5 (reason 0)_ Dec 17 15:58:34 [NetworkManager] <info> Activation (ttyACM0) Stage 2 of 5 (Device Configure) successful._ Dec 17 15:58:34 [NetworkManager] <info> Activation (ttyACM0) Stage 3 of 5 (IP Configure Start) scheduled._ Dec 17 15:58:34 [NetworkManager] <info> Activation (ttyACM0) Stage 2 of 5 (Device Configure) complete._ Dec 17 15:58:34 [NetworkManager] <info> Activation (ttyACM0) Stage 3 of 5 (IP Configure Start) started..._ Dec 17 15:58:34 [NetworkManager] <info> (ttyACM0): device state change: 5 -> 7 (reason 0)_ Dec 17 15:58:34 [NetworkManager] <info> starting PPP connection_ Dec 17 15:58:34 [NetworkManager] <info> pppd started with pid 14534_ Dec 17 15:58:34 [NetworkManager] <info> Activation (ttyACM0) Stage 3 of 5 (IP Configure Start) complete._ Dec 17 15:58:34 [pppd] Plugin /usr/lib64/pppd/2.4.5/nm-pppd-plugin.so loaded. Dec 17 15:58:34 [pppd] pppd 2.4.5 started by root, uid 0 Dec 17 15:58:34 [kernel] [615164.783106] PPP generic driver version 2.4.2 Dec 17 15:58:34 [pppd] Using interface ppp0 Dec 17 15:58:34 [pppd] Connect: ppp0 <--> /dev/ttyACM0 Dec 17 15:58:34 [pppd] PAP authentication succeeded Dec 17 15:58:34 [kernel] [615164.979138] PPP BSD Compression module registered Dec 17 15:58:34 [kernel] [615164.981515] PPP Deflate Compression module registered Dec 17 15:58:35 [pppd] local IP address 10.48.94.184 Dec 17 15:58:35 [pppd] remote IP address 10.6.6.6 Dec 17 15:58:35 [pppd] primary DNS address 172.30.139.17 Dec 17 15:58:35 [pppd] secondary DNS address 172.30.140.69 Dec 17 15:58:35 [NetworkManager] <info> PPP manager(IP Config Get) reply received._ Dec 17 15:58:35 [NetworkManager] <info> Activation (ttyACM0) Stage 4 of 5 (IP4 Configure Get) scheduled..._ Dec 17 15:58:35 [NetworkManager] <info> Activation (ttyACM0) Stage 4 of 5 (IP4 Configure Get) started..._ Dec 17 15:58:35 [NetworkManager] <info> Activation (ttyACM0) Stage 5 of 5 (IP Configure Commit) scheduled..._ Dec 17 15:58:35 [NetworkManager] <info> Activation (ttyACM0) Stage 4 of 5 (IP4 Configure Get) complete._ Dec 17 15:58:35 [NetworkManager] <info> Activation (ttyACM0) Stage 5 of 5 (IP Configure Commit) started..._ Dec 17 15:58:36 [NetworkManager] <info> (ppp0): writing resolv.conf to /sbin/resolvconf_ Dec 17 15:58:36 [NetworkManager] <info> Clearing nscd hosts cache._
Hmmm, "a bit longer to esteblish connection", what do you mean? simply I connect a phone, select PC Suite and try several times to connect and the same, see Messages_2. Trying via wvdial, no problem: # wvdial MTS_TM --> WvDial: Internet dialer version 1.61 --> Cannot get information for serial port. --> Initializing modem. --> Sending: ATZ OK --> Sending: ATQ0 V1 E1 S0=0 &C1 &D2 +FCLASS=0 ATQ0 V1 E1 S0=0 &C1 &D2 +FCLASS=0 OK --> Sending: AT +CGDCONT=1,"IP","net.mts.tm" AT +CGDCONT=1,"IP","net.mts.tm" OK --> Modem initialized. --> Idle Seconds = 300, disabling automatic reconnect. --> Sending: ATDT*99# --> Waiting for carrier. ATDT*99# CONNECT ~[7f]}#@!}!} } }2}#}$@#}!}$}%\}"}&} }*} } g}%~ --> Carrier detected. Waiting for prompt. ~[7f]}#@!}!} } }2}#}$@#}!}$}%\}"}&} }*} } g}%~ --> PPP negotiation detected. --> Starting pppd at Sun Dec 19 00:07:13 2010 --> Pid of pppd: 17615 --> Using interface ppp0 --> local IP address 172.16.44.144 --> remote IP address 10.6.6.6 --> primary DNS address 10.192.17.1 --> secondary DNS address 10.192.36.7 Maybe phone is somehow buggy? but I did not used extra develop repos.
Created attachment 257508 [details] Log of MM and NM (failture)
Your phone is not bugged. Modemmanager times out sooner then N900 connects. It was already fixed in modemmanager master (commit http://cgit.freedesktop.org/ModemManager/ModemManager/commit/?id=56665c19af431234ebe1b22cff9f0f9b9fb3d02f) and is part of modemmanager-0.4_p20101211. Can you reproduce your problem with modemmanager-0.4_p20101211?
Yep, All logs and traces were provided with version in the beginning. I have also checked the file mm-modem-nokia.c, it has the patch. But MM fails until modem-manager is not killed while N900 already being plugged. # eix modemmanager [I] net-misc/modemmanager Available versions: (~)0.3 [M](~)0.3_p20100401 0.4 (~)0.4_p20101211 {doc policykit test} Installed versions: 0.4_p20101211(23:10:17 01/08/11)(policykit -doc -test) Homepage: http://mail.gnome.org/archives/networkmanager-list/2008-July/msg00274.html Description: Modem and mobile broadband management libraries Jan 8 23:13:22 8doch7121ha38 kernel: usb 2-1: new high speed USB device using ehci_hcd and address 7 Jan 8 23:13:22 8doch7121ha38 kernel: cdc_acm 2-1:1.6: This device cannot do calls on its own. It is not a modem. Jan 8 23:13:22 8doch7121ha38 kernel: cdc_acm 2-1:1.6: ttyACM0: USB ACM device Jan 8 23:13:22 8doch7121ha38 kernel: cdc_ether 2-1:1.8: usb0: register 'cdc_ether' at usb-0000:00:1d.7-1, CDC Ethernet Device, ae:49:27:a1:c0:82 Jan 8 23:13:22 8doch7121ha38 NetworkManager[9308]: <error> [1294517602.203454] [nm-device-ethernet.c:730] real_update_permanent_hw_address(): (usb0): unable to read permanent MAC address (error 0) Jan 8 23:13:22 8doch7121ha38 modem-manager: (ttyACM0) opening serial port... Jan 8 23:13:22 8doch7121ha38 modem-manager: (ttyACM0): probe requested by plugin 'Nokia' Jan 8 23:13:23 8doch7121ha38 modem-manager: (ttyACM0) closing serial port... Jan 8 23:13:23 8doch7121ha38 modem-manager: (ttyACM0) opening serial port... Jan 8 23:13:23 8doch7121ha38 modem-manager: (Nokia): GSM modem /sys/devices/pci0000:00/0000:00:1d.7/usb2/2-1 claimed port ttyACM0 Jan 8 23:13:23 8doch7121ha38 modem-manager: Added modem /sys/devices/pci0000:00/0000:00:1d.7/usb2/2-1 Jan 8 23:13:23 8doch7121ha38 modem-manager: (tty/ttyACM0): outstanding support task prevents export of /sys/devices/pci0000:00/0000:00:1d.7/usb2/2-1 Jan 8 23:13:23 8doch7121ha38 modem-manager: (tty/ttyACM0): outstanding support task prevents export of /sys/devices/pci0000:00/0000:00:1d.7/usb2/2-1 Jan 8 23:13:33 8doch7121ha38 modem-manager: Got failure code 100: Unknown error Jan 8 23:13:33 8doch7121ha38 modem-manager: (ttyACM0) closing serial port... Jan 8 23:13:33 8doch7121ha38 modem-manager: Exported modem /sys/devices/pci0000:00/0000:00:1d.7/usb2/2-1 as /org/freedesktop/ModemManager/Modems/2 Jan 8 23:13:33 8doch7121ha38 modem-manager: (/org/freedesktop/ModemManager/Modems/2): VID 0x0421 PID 0x01C8 (usb) Jan 8 23:13:33 8doch7121ha38 modem-manager: (/org/freedesktop/ModemManager/Modems/2): data port is ttyACM0 Jan 8 23:13:33 8doch7121ha38 NetworkManager[9308]: <warn> (ttyACM0): failed to look up interface index Jan 8 23:13:51 8doch7121ha38 modem-manager: (ttyACM0) opening serial port... Jan 8 23:13:51 8doch7121ha38 modem-manager: Modem /org/freedesktop/ModemManager/Modems/2: state changed (disabled -> enabling) Jan 8 23:13:54 8doch7121ha38 modem-manager: Modem /org/freedesktop/ModemManager/Modems/2: state changed (enabling -> disabled) Jan 8 23:13:54 8doch7121ha38 modem-manager: (ttyACM0) closing serial port... Jan 8 23:13:54 8doch7121ha38 NetworkManager[9308]: <warn> GSM modem enable failed: (32) Serial command timed out Jan 8 23:13:55 8doch7121ha38 NetworkManager[9308]: <warn> Activation (ttyACM0) failed. Thank You
I see this problem too, even with modemmanager-4.0_p20110205. Interestingly, if I open /dev/ttyACM0 with minicom (which initialises it within 5s (fwiw,with AT S7=45 S0=0 L1 V1 X4 &c1 E1 Q0)), close it, and then try connecting again, the connection happens just fine. If I unplug and replug the cable, I need to do that all over again.
This may be because Nokia N900 eats the first character of the commands if they are issued immediately after opening /dev/ttyACM0. Here is how to demonstrate the bug without modemmanager: chat -V "" +++AT OK </dev/ttyACM0 >/dev/ttyACM0 Try this command several times. Many times you will have only two plusses out of three echoed back.
Still valid with 0.5.2.0?
Just tested it with 0.5.2.0 and it worked.
(In reply to comment #13) > Just tested it with 0.5.2.0 and it worked. Marking as fixed then.
