Summary: | net-misc/modemmanager fails on Nokia N900: GSM modem enable failed: (32) Serial command timed out | ||
---|---|---|---|
Product: | Gentoo Linux | Reporter: | Vasiliy Kotikov <elnone> |
Component: | Current packages | Assignee: | Robert Piasek (RETIRED) <dagger> |
Status: | RESOLVED FIXED | ||
Severity: | normal | CC: | ford_prefect, kbx, Marc-Antoine, nirbheek, tetromino, woldemar |
Priority: | High | Keywords: | Bug |
Version: | unspecified | ||
Hardware: | All | ||
OS: | Linux | ||
Whiteboard: | |||
Package list: | Runtime testing required: | --- | |
Attachments: |
ModemManager Debug
NetworkManager Debug Debug to /var/log/messages In case kernel config is required... Log of MM and NM (failture) |
Description
Vasiliy Kotikov
2010-12-16 08:14:21 UTC
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. |