Bug 622425

Summary: Huawei e1550 USB modem hangs up immediately after successful PPP auth
Product: [Fedora] Fedora Reporter: Ditesh Kumar <ditesh>
Component: NetworkManagerAssignee: Dan Williams <dcbw>
Status: CLOSED WONTFIX QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: medium Docs Contact:
Priority: low    
Version: 13CC: dcbw, desmond.armstrong, gokcen.eraslan, jklimes, m_runwal
Target Milestone: ---   
Target Release: ---   
Hardware: i686   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2011-06-28 14:48:22 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 Ditesh Kumar 2010-08-09 10:17:42 UTC
Description of problem:

Huawei e1550 modem is detected correctly but hangs up immediately after successful PPP/CHAP auth.

Version-Release number of selected component (if applicable):


How reproducible:


Steps to Reproduce:
1. Plug in USB Huawei e1550 modem
2. Configure using default settings for DiGi Malaysia (comes with NetworkManager)
3. Connect to the specified mobile broadband network
  
Actual results:

Disconnects immediately after successful PPP auth as shown in /var/log/messages show:

Aug  9 18:05:45 rhea kernel: usb 2-3: new high speed USB device using ehci_hcd and address 5
Aug  9 18:05:45 rhea kernel: usb 2-3: New USB device found, idVendor=12d1, idProduct=1446
Aug  9 18:05:45 rhea kernel: usb 2-3: New USB device strings: Mfr=2, Product=1, SerialNumber=0
Aug  9 18:05:45 rhea kernel: usb 2-3: Product: HUAWEI Mobile
Aug  9 18:05:45 rhea kernel: usb 2-3: Manufacturer: HUAWEI Technology
Aug  9 18:05:45 rhea kernel: scsi13 : usb-storage 2-3:1.0
Aug  9 18:05:45 rhea kernel: scsi14 : usb-storage 2-3:1.1
Aug  9 18:05:46 rhea usb_modeswitch: switching 12d1:1446 (HUAWEI Technology: HUAWEI Mobile)
Aug  9 18:05:46 rhea kernel: usb 2-3: USB disconnect, address 5
Aug  9 18:05:46 rhea pcscd: hotplug_libhal.c:313:get_driver() libhal_device_get_property_int org.freedesktop.Hal.NoSuchDevice: -1228926256
Aug  9 18:05:53 rhea kernel: usb 2-3: new high speed USB device using ehci_hcd and address 6
Aug  9 18:05:53 rhea kernel: usb 2-3: New USB device found, idVendor=12d1, idProduct=1001
Aug  9 18:05:53 rhea kernel: usb 2-3: New USB device strings: Mfr=2, Product=1, SerialNumber=0
Aug  9 18:05:53 rhea kernel: usb 2-3: Product: HUAWEI Mobile
Aug  9 18:05:53 rhea kernel: usb 2-3: Manufacturer: HUAWEI Technology
Aug  9 18:05:53 rhea kernel: option 2-3:1.0: GSM modem (1-port) converter detected
Aug  9 18:05:53 rhea kernel: usb 2-3: GSM modem (1-port) converter now attached to ttyUSB0
Aug  9 18:05:53 rhea kernel: option 2-3:1.1: GSM modem (1-port) converter detected
Aug  9 18:05:53 rhea kernel: usb 2-3: GSM modem (1-port) converter now attached to ttyUSB1
Aug  9 18:05:53 rhea kernel: option 2-3:1.2: GSM modem (1-port) converter detected
Aug  9 18:05:53 rhea kernel: usb 2-3: GSM modem (1-port) converter now attached to ttyUSB2
Aug  9 18:05:53 rhea kernel: scsi18 : usb-storage 2-3:1.3
Aug  9 18:05:53 rhea kernel: scsi19 : usb-storage 2-3:1.4
Aug  9 18:05:53 rhea usb_modeswitch: switched to 12d1:1001 (HUAWEI Technology: HUAWEI Mobile)
Aug  9 18:05:53 rhea modem-manager: (ttyUSB0) opening serial device...
Aug  9 18:05:55 rhea modem-manager: (ttyUSB0) closing serial device...
Aug  9 18:05:55 rhea modem-manager: (ttyUSB0) opening serial device...
Aug  9 18:05:55 rhea modem-manager: (Huawei): GSM modem /sys/devices/pci0000:00/0000:00:1d.7/usb2/2-3 claimed port ttyUSB0
Aug  9 18:05:55 rhea modem-manager: (ttyUSB0) closing serial device...
Aug  9 18:05:56 rhea modem-manager: (ttyUSB1) opening serial device...
Aug  9 18:05:56 rhea modem-manager: (ttyUSB2) opening serial device...
Aug  9 18:05:58 rhea modem-manager: (ttyUSB2) closing serial device...
Aug  9 18:05:58 rhea modem-manager: (Huawei): GSM modem /sys/devices/pci0000:00/0000:00:1d.7/usb2/2-3 claimed port ttyUSB2
Aug  9 18:05:58 rhea kernel: scsi 18:0:0:0: CD-ROM            HUAWEI   Mass Storage     2.31 PQ: 0 ANSI: 2
Aug  9 18:05:58 rhea kernel: scsi 19:0:0:0: Direct-Access     HUAWEI   MMC Storage      2.31 PQ: 0 ANSI: 2
Aug  9 18:05:58 rhea kernel: sr1: scsi-1 drive
Aug  9 18:05:58 rhea kernel: sr 18:0:0:0: Attached scsi generic sg2 type 5
Aug  9 18:05:58 rhea kernel: sd 19:0:0:0: Attached scsi generic sg3 type 0
Aug  9 18:05:58 rhea kernel: sd 19:0:0:0: [sdb] Attached SCSI removable disk
Aug  9 18:06:04 rhea modem-manager: (ttyUSB1) closing serial device...
Aug  9 18:06:04 rhea modem-manager: (Huawei): GSM modem /sys/devices/pci0000:00/0000:00:1d.7/usb2/2-3 claimed port ttyUSB1
Aug  9 18:06:04 rhea NetworkManager[1512]: <warn> (ttyUSB0): failed to look up interface index
Aug  9 18:06:04 rhea NetworkManager[1512]: <info> (ttyUSB0): new GSM device (driver: 'option1' ifindex: -1)
Aug  9 18:06:04 rhea NetworkManager[1512]: <info> (ttyUSB0): exported as /org/freedesktop/NetworkManager/Devices/3
Aug  9 18:06:04 rhea NetworkManager[1512]: <info> (ttyUSB0): now managed
Aug  9 18:06:04 rhea NetworkManager[1512]: <info> (ttyUSB0): device state change: 1 -> 2 (reason 2)
Aug  9 18:06:04 rhea NetworkManager[1512]: <info> (ttyUSB0): deactivating device (reason: 2).
Aug  9 18:06:04 rhea NetworkManager[1512]: <info> (ttyUSB0): device state change: 2 -> 3 (reason 0)
Aug  9 18:06:37 rhea NetworkManager[1512]: <info> Activation (ttyUSB0) starting connection 'DiGi'
Aug  9 18:06:37 rhea NetworkManager[1512]: <info> (ttyUSB0): device state change: 3 -> 4 (reason 0)
Aug  9 18:06:37 rhea NetworkManager[1512]: <info> Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) scheduled...
Aug  9 18:06:37 rhea NetworkManager[1512]: <info> Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) started...
Aug  9 18:06:37 rhea NetworkManager[1512]: <info> (ttyUSB0): device state change: 4 -> 6 (reason 0)
Aug  9 18:06:37 rhea NetworkManager[1512]: <info> Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) complete.
Aug  9 18:06:37 rhea NetworkManager[1512]: <info> Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) scheduled...
Aug  9 18:06:37 rhea NetworkManager[1512]: <info> Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) started...
Aug  9 18:06:37 rhea NetworkManager[1512]: <info> (ttyUSB0): device state change: 6 -> 4 (reason 0)
Aug  9 18:06:37 rhea NetworkManager[1512]: <info> Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) complete.
Aug  9 18:06:37 rhea modem-manager: (ttyUSB0) opening serial device...
Aug  9 18:06:37 rhea modem-manager: Modem /org/freedesktop/ModemManager/Modems/1: state changed (disabled -> enabling)
Aug  9 18:06:37 rhea modem-manager: (ttyUSB2) opening serial device...
Aug  9 18:06:37 rhea modem-manager: Modem /org/freedesktop/ModemManager/Modems/1: state changed (enabling -> enabled)
Aug  9 18:06:37 rhea modem-manager: Modem /org/freedesktop/ModemManager/Modems/1: state changed (enabled -> registered)
Aug  9 18:06:38 rhea modem-manager: Modem /org/freedesktop/ModemManager/Modems/1: state changed (registered -> connecting)
Aug  9 18:06:38 rhea modem-manager: Modem /org/freedesktop/ModemManager/Modems/1: state changed (connecting -> connected)
Aug  9 18:06:38 rhea NetworkManager[1512]: <info> Activation (ttyUSB0) Stage 2 of 5 (Device Configure) scheduled...
Aug  9 18:06:38 rhea NetworkManager[1512]: <info> Activation (ttyUSB0) Stage 2 of 5 (Device Configure) starting...
Aug  9 18:06:38 rhea NetworkManager[1512]: <info> (ttyUSB0): device state change: 4 -> 5 (reason 0)
Aug  9 18:06:38 rhea NetworkManager[1512]: <info> Activation (ttyUSB0) Stage 2 of 5 (Device Configure) successful.
Aug  9 18:06:38 rhea NetworkManager[1512]: <info> Activation (ttyUSB0) Stage 3 of 5 (IP Configure Start) scheduled.
Aug  9 18:06:38 rhea NetworkManager[1512]: <info> Activation (ttyUSB0) Stage 2 of 5 (Device Configure) complete.
Aug  9 18:06:38 rhea NetworkManager[1512]: <info> Activation (ttyUSB0) Stage 3 of 5 (IP Configure Start) started...
Aug  9 18:06:38 rhea NetworkManager[1512]: <info> (ttyUSB0): device state change: 5 -> 7 (reason 0)
Aug  9 18:06:38 rhea NetworkManager[1512]: <info> starting PPP connection
Aug  9 18:06:38 rhea NetworkManager[1512]: <info> pppd started with pid 13250
Aug  9 18:06:38 rhea NetworkManager[1512]: <info> Activation (ttyUSB0) Stage 3 of 5 (IP Configure Start) complete.
Aug  9 18:06:38 rhea pppd[13250]: Plugin /usr/lib/pppd/2.4.5/nm-pppd-plugin.so loaded.
Aug  9 18:06:38 rhea kernel: PPP generic driver version 2.4.2
Aug  9 18:06:38 rhea pppd[13250]: pppd 2.4.5 started by root, uid 0
Aug  9 18:06:38 rhea pppd[13250]: Using interface ppp0
Aug  9 18:06:38 rhea pppd[13250]: Connect: ppp0 <--> /dev/ttyUSB0
Aug  9 18:06:38 rhea pppd[13250]: PAP authentication succeeded
Aug  9 18:06:39 rhea pppd[13250]: Modem hangup
Aug  9 18:06:39 rhea pppd[13250]: Connection terminated.
Aug  9 18:06:39 rhea NetworkManager[1512]: <info> (ttyUSB0): device state change: 7 -> 9 (reason 5)
Aug  9 18:06:39 rhea NetworkManager[1512]: <info> Marking connection 'DiGi' invalid.
Aug  9 18:06:39 rhea NetworkManager[1512]: <warn> Activation (ttyUSB0) failed.
Aug  9 18:06:39 rhea NetworkManager[1512]: <info> (ttyUSB0): device state change: 9 -> 3 (reason 0)
Aug  9 18:06:39 rhea NetworkManager[1512]: <info> (ttyUSB0): deactivating device (reason: 0).
Aug  9 18:06:39 rhea modem-manager: (ttyUSB0) closing serial device...
Aug  9 18:06:39 rhea modem-manager: Modem /org/freedesktop/ModemManager/Modems/1: state changed (connected -> disconnecting)
Aug  9 18:06:39 rhea modem-manager: Modem /org/freedesktop/ModemManager/Modems/1: state changed (disconnecting -> connected)
Aug  9 18:06:39 rhea NetworkManager[1512]: <info> Policy set 'Auto aasite01' (wlan0) as default for IPv4 routing and DNS.
Aug  9 18:06:39 rhea NetworkManager[1512]: <info> Policy set 'Auto aasite01' (wlan0) as default for IPv4 routing and DNS.
Aug  9 18:06:39 rhea NetworkManager[1512]: <info> disconnect failed: (32) The serial port is not open.
Aug  9 18:06:40 rhea pppd[13250]: Exit.
Aug  9 18:06:40 rhea dbus-daemon: [system] Rejected send message, 1 matched rules; type="error", sender=":1.1" (uid=0 pid=1512 comm="NetworkManager) interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" requested_reply=0 destination=":1.119" (uid=0 pid=13250 comm="/usr/sbin/pppd))


Expected results:

Correctly connect to the DiGi network.

Additional info:

Using DiGi mobile broadband network in Malaysia

Comment 1 Jirka Klimes 2010-11-30 11:24:33 UTC
Did it work with previous versions?

I suggest you try debugging pppd according to instructions in "Debugging NetworkManager 0.8.x 3G connections" of http://live.gnome.org/NetworkManager/Debugging

NM_PPP_DEBUG=1 /usr/sbin/NetworkManager --no-daemon
will trigger pppd logs.

Comment 2 Desmond 2011-05-29 16:28:45 UTC
Having fedora 15 running nicely is great.
I tried to install the Vodafone mobile broadband but did not succeed.

What is worse, though, is that after this exercise neither Wi-Fi nor wired Lan work anymore.

To make the system work again on the Wi-Fi I had to remove the mobile file from:-

/etc/NetworkManager/system-connections/

Comment 3 Bug Zapper 2011-06-01 11:49:46 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 4 Runwalsoft 2011-06-14 14:29:02 UTC
This is not even working for Fedora 15.

Comment 5 Bug Zapper 2011-06-28 14:48:22 UTC
Fedora 13 changed to end-of-life (EOL) status on 2011-06-25. Fedora 13 is 
no longer maintained, which means that it will not receive any further 
security or bug fix updates. As a result we are closing this bug.

If you can reproduce this bug against a currently maintained version of 
Fedora please feel free to reopen this bug against that version.

Thank you for reporting this bug and we are sorry it could not be fixed.