Gentoo Websites Logo
Go to: Gentoo Home Documentation Forums Lists Bugs Planet Store Wiki Get Gentoo!
Bug 348849 - net-misc/modemmanager fails on Nokia N900: GSM modem enable failed: (32) Serial command timed out
Summary: net-misc/modemmanager fails on Nokia N900: GSM modem enable failed: (32) Seri...
Status: RESOLVED FIXED
Alias: None
Product: Gentoo Linux
Classification: Unclassified
Component: Current packages (show other bugs)
Hardware: All Linux
: High normal
Assignee: Robert Piasek (RETIRED)
URL:
Whiteboard:
Keywords: Bug
Depends on:
Blocks:
 
Reported: 2010-12-16 08:14 UTC by Vasiliy Kotikov
Modified: 2012-04-09 14:57 UTC (History)
6 users (show)

See Also:
Package list:
Runtime testing required: ---


Attachments
ModemManager Debug (MM_Debug_N900.txt,8.20 KB, text/plain)
2010-12-16 08:15 UTC, Vasiliy Kotikov
Details
NetworkManager Debug (NM_Debug_N900.txt,26.04 KB, text/plain)
2010-12-16 08:16 UTC, Vasiliy Kotikov
Details
Debug to /var/log/messages (Messages,56.96 KB, text/plain)
2010-12-16 08:17 UTC, Vasiliy Kotikov
Details
In case kernel config is required... (config,65.33 KB, text/plain)
2010-12-16 08:21 UTC, Vasiliy Kotikov
Details
Log of MM and NM (failture) (Messages_2,40.40 KB, text/plain)
2010-12-18 19:14 UTC, Vasiliy Kotikov
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Vasiliy Kotikov 2010-12-16 08:14:21 UTC
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
Comment 1 Vasiliy Kotikov 2010-12-16 08:15:38 UTC
Created attachment 257276 [details]
ModemManager Debug
Comment 2 Vasiliy Kotikov 2010-12-16 08:16:04 UTC
Created attachment 257278 [details]
NetworkManager Debug
Comment 3 Vasiliy Kotikov 2010-12-16 08:17:58 UTC
Created attachment 257279 [details]
Debug to /var/log/messages

This is a case when MM's managed to connect...
Comment 4 Vasiliy Kotikov 2010-12-16 08:21:29 UTC
Created attachment 257281 [details]
In case kernel config is required...
Comment 5 Robert Piasek (RETIRED) gentoo-dev 2010-12-17 16:02:51 UTC
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._
Comment 6 Vasiliy Kotikov 2010-12-18 19:11:12 UTC
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.
Comment 7 Vasiliy Kotikov 2010-12-18 19:14:37 UTC
Created attachment 257508 [details]
Log of MM and NM (failture)
Comment 8 Robert Piasek (RETIRED) gentoo-dev 2011-01-06 15:15:24 UTC
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?

Comment 9 Vasiliy Kotikov 2011-01-08 20:21:22 UTC
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
Comment 10 Arun Raghavan (RETIRED) gentoo-dev 2011-02-12 06:13:42 UTC
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.
Comment 11 Alexander E. Patrakov 2011-02-17 22:55:10 UTC
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.
Comment 12 Pacho Ramos gentoo-dev 2012-04-06 15:18:23 UTC
Still valid with 0.5.2.0?
Comment 13 Kristian 2012-04-09 13:19:49 UTC
Just tested it with 0.5.2.0 and it worked.
Comment 14 Alexandre Rostovtsev (RETIRED) gentoo-dev 2012-04-09 14:57:22 UTC
(In reply to comment #13)
> Just tested it with 0.5.2.0 and it worked.

Marking as fixed then.