Bug 627501

Summary: ModemManager fails to handle Huawei E160 correctly
Product: [Fedora] Fedora Reporter: Stefan Assmann <sassmann>
Component: ModemManagerAssignee: Dan Williams <dcbw>
Status: CLOSED CURRENTRELEASE QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: medium Docs Contact:
Priority: low    
Version: 15CC: dcbw
Target Milestone: ---   
Target Release: ---   
Hardware: All   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2011-07-18 23:16:13 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Stefan Assmann 2010-08-26 08:21:05 UTC
Description of problem:
When I plug in a Huawei E160 USB UMTS modem I see the following in /var/log/messages

Aug 26 10:15:03 eeepc kernel: usb 1-4: new high speed USB device using ehci_hcd and address 7
Aug 26 10:15:03 eeepc kernel: usb 1-4: New USB device found, idVendor=12d1, idProduct=1003
Aug 26 10:15:03 eeepc kernel: usb 1-4: New USB device strings: Mfr=3, Product=2, SerialNumber=0
Aug 26 10:15:03 eeepc kernel: usb 1-4: Product: HUAWEI Mobile
Aug 26 10:15:03 eeepc kernel: usb 1-4: Manufacturer: HUAWEI Technology
Aug 26 10:15:03 eeepc kernel: scsi12 : usb-storage 1-4:1.0
Aug 26 10:15:03 eeepc kernel: usb 1-4: USB disconnect, address 7
Aug 26 10:15:17 eeepc ntpd[1177]: 0.0.0.0 c615 05 clock_sync
Aug 26 10:15:20 eeepc kernel: usb 1-4: new high speed USB device using ehci_hcd and address 8
Aug 26 10:15:20 eeepc kernel: usb 1-4: New USB device found, idVendor=12d1, idProduct=1003
Aug 26 10:15:20 eeepc kernel: usb 1-4: New USB device strings: Mfr=3, Product=2, SerialNumber=0
Aug 26 10:15:20 eeepc kernel: usb 1-4: Product: HUAWEI Mobile
Aug 26 10:15:20 eeepc kernel: usb 1-4: Manufacturer: HUAWEI Technology
Aug 26 10:15:20 eeepc kernel: option 1-4:1.0: GSM modem (1-port) converter detected
Aug 26 10:15:20 eeepc kernel: usb 1-4: GSM modem (1-port) converter now attached to ttyUSB0
Aug 26 10:15:20 eeepc kernel: option 1-4:1.1: GSM modem (1-port) converter detected
Aug 26 10:15:20 eeepc kernel: usb 1-4: GSM modem (1-port) converter now attached to ttyUSB1
Aug 26 10:15:20 eeepc kernel: scsi15 : usb-storage 1-4:1.2
Aug 26 10:15:20 eeepc kernel: scsi16 : usb-storage 1-4:1.3
Aug 26 10:15:20 eeepc modem-manager: (ttyUSB0) opening serial device...
Aug 26 10:15:23 eeepc modem-manager: (ttyUSB0) closing serial device...
Aug 26 10:15:23 eeepc modem-manager: (ttyUSB0) opening serial device...
Aug 26 10:15:23 eeepc modem-manager: (Huawei): GSM modem /sys/devices/pci0000:00/0000:00:1d.7/usb1/1-4 claimed port ttyUSB0
Aug 26 10:15:23 eeepc modem-manager: (ttyUSB1) opening serial device...
Aug 26 10:15:23 eeepc modem-manager: (ttyUSB1) closing serial device...
Aug 26 10:15:23 eeepc modem-manager: (Huawei): GSM modem /sys/devices/pci0000:00/0000:00:1d.7/usb1/1-4 claimed port ttyUSB1
Aug 26 10:15:25 eeepc kernel: scsi 15:0:0:0: CD-ROM            HUAWEI   Mass Storage     2.31 PQ: 0 ANSI: 2
Aug 26 10:15:25 eeepc kernel: scsi 16:0:0:0: Direct-Access     HUAWEI   MMC Storage      2.31 PQ: 0 ANSI: 2
Aug 26 10:15:25 eeepc kernel: sr0: scsi-1 drive
Aug 26 10:15:25 eeepc kernel: sr 15:0:0:0: Attached scsi generic sg1 type 5
Aug 26 10:15:25 eeepc kernel: sd 16:0:0:0: Attached scsi generic sg2 type 0
Aug 26 10:15:25 eeepc kernel: sd 16:0:0:0: [sdb] Attached SCSI removable disk
Aug 26 10:15:30 eeepc modem-manager: (ttyUSB0) closing serial device...
Aug 26 10:15:30 eeepc NetworkManager[947]: <warn> (ttyUSB0): failed to look up interface index
Aug 26 10:15:30 eeepc NetworkManager[947]: <info> (ttyUSB0): new GSM device (driver: 'option1' ifindex: -1)
Aug 26 10:15:30 eeepc NetworkManager[947]: <info> (ttyUSB0): exported as /org/freedesktop/NetworkManager/Devices/4
Aug 26 10:15:30 eeepc NetworkManager[947]: <info> (ttyUSB0): now managed
Aug 26 10:15:30 eeepc NetworkManager[947]: <info> (ttyUSB0): device state change: 1 -> 2 (reason 2)
Aug 26 10:15:30 eeepc NetworkManager[947]: <info> (ttyUSB0): deactivating device (reason: 2).
Aug 26 10:15:30 eeepc NetworkManager[947]: <info> (ttyUSB0): device state change: 2 -> 3 (reason 0)

When I try to establish a connection the following appears (the connection does not get established)

Aug 26 10:17:09 eeepc NetworkManager[947]: <info> Activation (ttyUSB0) starting connection 'AldiTalk/MedionMobile Volume rate/30 Day Flatrate 1'
Aug 26 10:17:09 eeepc NetworkManager[947]: <info> (ttyUSB0): device state change: 3 -> 4 (reason 0)
Aug 26 10:17:09 eeepc NetworkManager[947]: <info> Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) scheduled...
Aug 26 10:17:09 eeepc NetworkManager[947]: <info> Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) started...
Aug 26 10:17:09 eeepc NetworkManager[947]: <info> (ttyUSB0): device state change: 4 -> 6 (reason 0)
Aug 26 10:17:09 eeepc NetworkManager[947]: <info> Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) complete.
Aug 26 10:17:09 eeepc NetworkManager[947]: <info> Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) scheduled...
Aug 26 10:17:09 eeepc NetworkManager[947]: <info> Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) started...
Aug 26 10:17:09 eeepc NetworkManager[947]: <info> (ttyUSB0): device state change: 6 -> 4 (reason 0)
Aug 26 10:17:09 eeepc NetworkManager[947]: <info> Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) complete.
Aug 26 10:17:09 eeepc modem-manager: (ttyUSB0) opening serial device...
Aug 26 10:17:09 eeepc modem-manager: Modem /org/freedesktop/ModemManager/Modems/2: state changed (disabled -> enabling)
Aug 26 10:17:09 eeepc modem-manager: (ttyUSB1) opening serial device...
Aug 26 10:17:09 eeepc modem-manager: Modem /org/freedesktop/ModemManager/Modems/2: state changed (enabling -> disabled)
Aug 26 10:17:09 eeepc modem-manager: (ttyUSB0) closing serial device...
Aug 26 10:17:09 eeepc modem-manager: (ttyUSB1) closing serial device...
Aug 26 10:17:09 eeepc NetworkManager[947]: <warn> GSM modem enable failed: (32) Failed to find a usable modem character set
Aug 26 10:17:09 eeepc NetworkManager[947]: <info> (ttyUSB0): device state change: 4 -> 9 (reason 28)
Aug 26 10:17:09 eeepc NetworkManager[947]: <info> Marking connection 'AldiTalk/MedionMobile Volume rate/30 Day Flatrate 1' invalid.
Aug 26 10:17:09 eeepc NetworkManager[947]: <warn> Activation (ttyUSB0) failed.
Aug 26 10:17:09 eeepc NetworkManager[947]: <info> (ttyUSB0): device state change: 9 -> 3 (reason 0)
Aug 26 10:17:09 eeepc NetworkManager[947]: <info> (ttyUSB0): deactivating device (reason: 0).

I tried UMTSMon and it works there.

Version-Release number of selected component (if applicable):
NetworkManager-0.8.1-1.fc13.i686
ModemManager-0.4-4.git20100720.fc13.i686

Note after resetting the device with
usb_modeswitch -R -v 12d1 -p 1003
it works also with NetworkManager.

How reproducible:
always

Steps to Reproduce:
1. plugin E160 USB modem
2. try to establish connection with NM

Comment 1 Stefan Assmann 2010-08-26 08:24:05 UTC
usb_modeswitch -R -v 12d1 -p 1003

results in:
Aug 26 10:22:25 eeepc kernel: option: option_instat_callback: error -108
Aug 26 10:22:25 eeepc kernel: option1 ttyUSB0: GSM modem (1-port) converter now disconnected from ttyUSB0
Aug 26 10:22:25 eeepc kernel: option 1-4:1.0: device disconnected
Aug 26 10:22:25 eeepc kernel: option1 ttyUSB1: GSM modem (1-port) converter now disconnected from ttyUSB1
Aug 26 10:22:25 eeepc kernel: option 1-4:1.1: device disconnected
Aug 26 10:22:25 eeepc NetworkManager[947]: <info> (ttyUSB0): now unmanaged
Aug 26 10:22:25 eeepc NetworkManager[947]: <info> (ttyUSB0): device state change: 3 -> 1 (reason 36)
Aug 26 10:22:25 eeepc NetworkManager[947]: <info> (ttyUSB0): cleaning up...
Aug 26 10:22:25 eeepc NetworkManager[947]: <info> (ttyUSB0): taking down device.
Aug 26 10:22:25 eeepc kernel: usb 1-4: reset high speed USB device using ehci_hcd and address 8
Aug 26 10:22:25 eeepc kernel: option 1-4:1.1: GSM modem (1-port) converter detected
Aug 26 10:22:25 eeepc kernel: usb 1-4: GSM modem (1-port) converter now attached to ttyUSB0
Aug 26 10:22:25 eeepc kernel: option 1-4:1.0: GSM modem (1-port) converter detected
Aug 26 10:22:25 eeepc kernel: usb 1-4: GSM modem (1-port) converter now attached to ttyUSB1
Aug 26 10:22:25 eeepc modem-manager: (ttyUSB1) opening serial device...
Aug 26 10:22:28 eeepc modem-manager: (ttyUSB1) closing serial device...
Aug 26 10:22:28 eeepc modem-manager: (ttyUSB1) opening serial device...
Aug 26 10:22:28 eeepc modem-manager: (Huawei): GSM modem /sys/devices/pci0000:00/0000:00:1d.7/usb1/1-4 claimed port ttyUSB1
Aug 26 10:22:28 eeepc modem-manager: (ttyUSB1) closing serial device...
Aug 26 10:22:28 eeepc modem-manager: (ttyUSB0) opening serial device...
Aug 26 10:22:36 eeepc modem-manager: (ttyUSB0) closing serial device...
Aug 26 10:22:36 eeepc modem-manager: (Huawei): GSM modem /sys/devices/pci0000:00/0000:00:1d.7/usb1/1-4 claimed port ttyUSB0
Aug 26 10:22:36 eeepc NetworkManager[947]: <warn> (ttyUSB1): failed to look up interface index
Aug 26 10:22:36 eeepc NetworkManager[947]: <info> (ttyUSB1): new GSM device (driver: 'option1' ifindex: -1)
Aug 26 10:22:36 eeepc NetworkManager[947]: <info> (ttyUSB1): exported as /org/freedesktop/NetworkManager/Devices/5
Aug 26 10:22:36 eeepc NetworkManager[947]: <info> (ttyUSB1): now managed
Aug 26 10:22:36 eeepc NetworkManager[947]: <info> (ttyUSB1): device state change: 1 -> 2 (reason 2)
Aug 26 10:22:36 eeepc NetworkManager[947]: <info> (ttyUSB1): deactivating device (reason: 2).
Aug 26 10:22:36 eeepc NetworkManager[947]: <info> (ttyUSB1): device state change: 2 -> 3 (reason 0)

After that the SIM PIN unlock dialog appears and everything is fine.

Comment 2 Bug Zapper 2011-06-01 10:22:22 UTC
This message is a reminder that Fedora 13 is nearing its end of life.
Approximately 30 (thirty) days from now Fedora will stop maintaining
and issuing updates for Fedora 13.  It is Fedora's policy to close all
bug reports from releases that are no longer maintained.  At that time
this bug will be closed as WONTFIX if it remains open with a Fedora 
'version' of '13'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version prior to Fedora 13's end of life.

Bug Reporter: Thank you for reporting this issue and we are sorry that 
we may not be able to fix it before Fedora 13 is end of life.  If you 
would still like to see this bug fixed and are able to reproduce it 
against a later version of Fedora please change the 'version' of this 
bug to the applicable version.  If you are unable to change the version, 
please add a comment here and someone will do it for you.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events.  Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

The process we are following is described here: 
http://fedoraproject.org/wiki/BugZappers/HouseKeeping

Comment 3 Dan Williams 2011-07-18 23:16:13 UTC
Is this issue fixed with latest MM testing updates for F15 and F14?  Specifically:

https://admin.fedoraproject.org/updates/ModemManager-0.4.998-1.git20110706.fc15

there was a previously an issue with handling character sets, but that's been fixed.  Try that update; it should fix the issue of "unable to find a usable character set".

Comment 4 Stefan Assmann 2011-07-19 09:53:46 UTC
Works nicely using
ModemManager-0.4.998-1.git20110706.fc15.i686
I had issues previously with F15 but this update fixes it.

Thanks Dan!