Bug 724891

Summary: Mobile Broadband connection stopped working
Product: [Fedora] Fedora Reporter: Maciej Sitarz <macieksitarz+redhatbugzilla>
Component: NetworkManagerAssignee: Dan Williams <dcbw>
Status: CLOSED CURRENTRELEASE QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: medium Docs Contact:
Priority: unspecified    
Version: 14CC: dcbw, jklimes
Target Milestone: ---   
Target Release: ---   
Hardware: x86_64   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2011-09-14 10:51:02 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Attachments:
Description Flags
NetworkManager debug log
none
modem-manager debug log none

Description Maciej Sitarz 2011-07-22 08:15:11 UTC
######## Description of problem:
Mobile Broadband connection is not working, I suspect that it stopped working after some upgrades I did, but don't know which one exactly.
The connection worked before, so the connection setup/profile should be OK.

I checked yum.log and recently there was an update:
Jul 12 19:47:08 Updated: 1:kde-plasma-networkmanagement-0.9-0.41.1.20110616git.fc14.x86_64
Jul 12 19:47:11 Updated: 1:kde-plasma-networkmanagement-libs-0.9-0.41.1.20110616git.fc14.x86_64

I tried to downgrade the packages but with no luck (logs from the downgrade at the very bottom)

Version-Release number of selected component (if applicable):
kde-plasma-networkmanagement-0.9-0.41.1.20110616git.fc14.x86_64
kde-plasma-networkmanagement-libs-0.9-0.41.1.20110616git.fc14.x86_64
NetworkManager-0.8.4-1.fc14.x86_64
NetworkManager-glib-0.8.4-1.fc14.x86_64
NetworkManager-gnome-0.8.4-1.fc14.x86_64
NetworkManager-openconnect-0.8.1-1.fc14.x86_64
NetworkManager-openvpn-0.8.1-1.fc14.x86_64
NetworkManager-pptp-0.8.1-1.fc14.x86_64
NetworkManager-vpnc-0.8.1-1.fc14.x86_64


######## How reproducible:
Every time

######## Steps to Reproduce:
1. Plug-in GSM modem
2. Using KDE network manager applet start the broadband connection

######## Actual results:
Broadband connection is not established

######## Expected results:
Broadband connection should be established successfully as it was working few days ago.

######## Additional info:

Logs after GSM Modem inserted:

Jul 22 09:33:49 msitarz kernel: [ 4625.951407] usb 2-1.1: new high speed USB device using ehci_hcd and address 6
Jul 22 09:33:49 msitarz kernel: [ 4626.029118] usb 2-1.1: New USB device found, idVendor=12d1, idProduct=1446
Jul 22 09:33:49 msitarz kernel: [ 4626.029125] usb 2-1.1: New USB device strings: Mfr=3, Product=2, SerialNumber=0
Jul 22 09:33:49 msitarz kernel: [ 4626.029130] usb 2-1.1: Product: HUAWEI Mobile
Jul 22 09:33:49 msitarz kernel: [ 4626.029133] usb 2-1.1: Manufacturer: HUAWEI Technology
Jul 22 09:33:49 msitarz kernel: [ 4626.031332] scsi38 : usb-storage 2-1.1:1.0
Jul 22 09:33:49 msitarz kernel: [ 4626.031716] scsi39 : usb-storage 2-1.1:1.1
Jul 22 09:33:49 msitarz mtp-probe: checking bus 2, device 6: "/sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.1"
Jul 22 09:33:49 msitarz mtp-probe: bus: 2, device: 6 was not an MTP device
Jul 22 09:33:50 msitarz usb_modeswitch: switching 12d1:1446 (HUAWEI Technology: HUAWEI Mobile)
Jul 22 09:33:50 msitarz kernel: [ 4626.796568] usb 2-1.1: USB disconnect, address 6
Jul 22 09:33:55 msitarz kernel: [ 4631.829282] usb 2-1.1: new high speed USB device using ehci_hcd and address 7
Jul 22 09:33:55 msitarz kernel: [ 4631.907224] usb 2-1.1: New USB device found, idVendor=12d1, idProduct=140c
Jul 22 09:33:55 msitarz kernel: [ 4631.907231] usb 2-1.1: New USB device strings: Mfr=3, Product=2, SerialNumber=0
Jul 22 09:33:55 msitarz kernel: [ 4631.907236] usb 2-1.1: Product: HUAWEI Mobile
Jul 22 09:33:55 msitarz kernel: [ 4631.907239] usb 2-1.1: Manufacturer: HUAWEI Technology
Jul 22 09:33:55 msitarz kernel: [ 4631.910389] option 2-1.1:1.0: GSM modem (1-port) converter detected
Jul 22 09:33:55 msitarz kernel: [ 4631.910577] usb 2-1.1: GSM modem (1-port) converter now attached to ttyUSB0
Jul 22 09:33:55 msitarz kernel: [ 4631.911059] option 2-1.1:1.1: GSM modem (1-port) converter detected
Jul 22 09:33:55 msitarz kernel: [ 4631.911217] usb 2-1.1: GSM modem (1-port) converter now attached to ttyUSB1
Jul 22 09:33:55 msitarz kernel: [ 4631.911486] option 2-1.1:1.2: GSM modem (1-port) converter detected
Jul 22 09:33:55 msitarz kernel: [ 4631.911618] usb 2-1.1: GSM modem (1-port) converter now attached to ttyUSB2
Jul 22 09:33:55 msitarz kernel: [ 4631.911900] option 2-1.1:1.3: GSM modem (1-port) converter detected
Jul 22 09:33:55 msitarz kernel: [ 4631.912048] usb 2-1.1: GSM modem (1-port) converter now attached to ttyUSB3
Jul 22 09:33:55 msitarz kernel: [ 4631.912752] scsi44 : usb-storage 2-1.1:1.4
Jul 22 09:33:55 msitarz kernel: [ 4631.913440] scsi45 : usb-storage 2-1.1:1.5
Jul 22 09:33:55 msitarz mtp-probe: checking bus 2, device 7: "/sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.1"
Jul 22 09:33:55 msitarz mtp-probe: bus: 2, device: 7 was not an MTP device
Jul 22 09:33:55 msitarz modem-manager: (ttyUSB0) opening serial device...
Jul 22 09:33:56 msitarz kernel: [ 4632.914360] scsi 44:0:0:0: CD-ROM            HUAWEI   Mass Storage     2.31 PQ: 0 ANSI: 2
Jul 22 09:33:56 msitarz kernel: [ 4632.914609] scsi 45:0:0:0: Direct-Access     HUAWEI   SD Storage       2.31 PQ: 0 ANSI: 2
Jul 22 09:33:56 msitarz usb_modeswitch: switched to 12d1:140c (HUAWEI Technology: HUAWEI Mobile)
Jul 22 09:33:56 msitarz kernel: [ 4632.922197] sr1: scsi-1 drive
Jul 22 09:33:56 msitarz kernel: [ 4632.922496] sr 44:0:0:0: Attached scsi generic sg2 type 5
Jul 22 09:33:56 msitarz kernel: [ 4632.924694] sd 45:0:0:0: Attached scsi generic sg3 type 0
Jul 22 09:33:56 msitarz kernel: [ 4632.930449] sd 45:0:0:0: [sdb] Attached SCSI removable disk
Jul 22 09:33:57 msitarz modem-manager: (ttyUSB0) closing serial device...
Jul 22 09:33:57 msitarz modem-manager: (ttyUSB0) opening serial device...
Jul 22 09:33:57 msitarz modem-manager: (Huawei): GSM modem /sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.1 claimed port ttyUSB0
Jul 22 09:33:57 msitarz modem-manager: (ttyUSB0) closing serial device...
Jul 22 09:33:58 msitarz modem-manager: (ttyUSB3) opening serial device...
Jul 22 09:33:58 msitarz modem-manager: (ttyUSB1) opening serial device...
Jul 22 09:33:58 msitarz modem-manager: (ttyUSB2) opening serial device...
Jul 22 09:33:58 msitarz modem-manager: (ttyUSB3) closing serial device...
Jul 22 09:33:58 msitarz modem-manager: (Huawei): GSM modem /sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.1 claimed port ttyUSB3
Jul 22 09:34:06 msitarz modem-manager: (ttyUSB1) closing serial device...
Jul 22 09:34:06 msitarz modem-manager: (ttyUSB2) closing serial device...
Jul 22 09:34:06 msitarz modem-manager: (Huawei): GSM modem /sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.1 claimed port ttyUSB1
Jul 22 09:34:06 msitarz modem-manager: (Huawei): GSM modem /sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.1 claimed port ttyUSB2
Jul 22 09:34:06 msitarz NetworkManager[1596]: <warn> (ttyUSB0): failed to look up interface index
Jul 22 09:34:06 msitarz NetworkManager[1596]: <info> (ttyUSB0): new GSM device (driver: 'option1' ifindex: -1)
Jul 22 09:34:06 msitarz NetworkManager[1596]: <info> (ttyUSB0): exported as /org/freedesktop/NetworkManager/Devices/6
Jul 22 09:34:06 msitarz NetworkManager[1596]: <info> (ttyUSB0): now managed
Jul 22 09:34:06 msitarz NetworkManager[1596]: <info> (ttyUSB0): device state change: 1 -> 2 (reason 2)
Jul 22 09:34:06 msitarz NetworkManager[1596]: <info> (ttyUSB0): deactivating device (reason: 2).
Jul 22 09:34:06 msitarz NetworkManager[1596]: <info> (ttyUSB0): device state change: 2 -> 3 (reason 0)


GSM modem tries to connect, after I press the broadband profile to connect:

Jul 22 09:34:49 msitarz modem-manager: (ttyUSB0) opening serial device...
Jul 22 09:34:49 msitarz modem-manager: Modem /org/freedesktop/ModemManager/Modems/4: state changed (disabled -> enabling)
Jul 22 09:34:49 msitarz NetworkManager[1596]: <info> Activation (ttyUSB0) starting connection 'iPlus'
Jul 22 09:34:49 msitarz NetworkManager[1596]: <info> (ttyUSB0): device state change: 3 -> 4 (reason 0)
Jul 22 09:34:49 msitarz NetworkManager[1596]: <info> Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) scheduled...
Jul 22 09:34:49 msitarz NetworkManager[1596]: <info> Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) started...
Jul 22 09:34:49 msitarz NetworkManager[1596]: <info> Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) complete.
Jul 22 09:34:49 msitarz modem-manager: Modem /org/freedesktop/ModemManager/Modems/4: state changed (enabling -> disabled)
Jul 22 09:34:49 msitarz modem-manager: (ttyUSB0) closing serial device...
Jul 22 09:34:49 msitarz NetworkManager[1596]: <warn> GSM modem enable failed: (32) Modem is already being flashed.
Jul 22 09:34:49 msitarz NetworkManager[1596]: <info> (ttyUSB0): device state change: 4 -> 9 (reason 28)
Jul 22 09:34:49 msitarz NetworkManager[1596]: <info> Marking connection 'iPlus' invalid.
Jul 22 09:34:49 msitarz NetworkManager[1596]: <warn> Activation (ttyUSB0) failed.
Jul 22 09:34:49 msitarz NetworkManager[1596]: <info> (ttyUSB0): device state change: 9 -> 3 (reason 0)
Jul 22 09:34:49 msitarz NetworkManager[1596]: <info> (ttyUSB0): deactivating device (reason: 0).
Jul 22 09:34:49 msitarz NetworkManager[1596]: <info> Policy set 'plum' (wlan0) as default for IPv4 routing and DNS.
Jul 22 09:34:49 msitarz NetworkManager[1596]: <info> Policy set 'plum' (wlan0) as default for IPv4 routing and DNS.



Yum ddowngrade logs:
# yum downgrade kde-plasma-networkmanagement
Loaded plugins: fastestmirror, ibm-cds-plugin, ibm-repository, langpacks, presto, refresh-packagekit
Adding en_US to language list
Setting up Downgrade Process
Loading mirror speeds from cached hostfile
 * fedora: sunsite.icm.edu.pl
 * rpmfusion-free: ftp.icm.edu.pl
 * rpmfusion-free-updates: ftp.icm.edu.pl
 * rpmfusion-nonfree: ftp.icm.edu.pl
 * rpmfusion-nonfree-updates: ftp.icm.edu.pl
 * updates: sunsite.icm.edu.pl
Resolving Dependencies
--> Running transaction check
---> Package kde-plasma-networkmanagement.x86_64 1:0.9-0.25.20100920.fc14 set to be downgraded
--> Processing Dependency: knetworkmanager-libs(x86-64) = 1:0.9-0.25.20100920.fc14 for package: 1:kde-plasma-networkmanagement-0.9-0.25.20100920.fc14.x86_64
---> Package kde-plasma-networkmanagement.x86_64 1:0.9-0.41.1.20110616git.fc14 set to be erased
--> Finished Dependency Resolution
Error: Package: 1:kde-plasma-networkmanagement-0.9-0.25.20100920.fc14.x86_64 (fedora)
           Requires: knetworkmanager-libs(x86-64) = 1:0.9-0.25.20100920.fc14
           Available: 1:knetworkmanager-libs-0.9-0.25.20100920.fc14.x86_64 (fedora)
               knetworkmanager-libs(x86-64) = 1:0.9-0.25.20100920.fc14
Error: Package: 1:kde-plasma-networkmanagement-libs-0.9-0.41.1.20110616git.fc14.x86_64 (@updates)
           Requires: kde-plasma-networkmanagement = 1:0.9-0.41.1.20110616git.fc14
           Removing: 1:kde-plasma-networkmanagement-0.9-0.41.1.20110616git.fc14.x86_64 (@updates)
               kde-plasma-networkmanagement = 1:0.9-0.41.1.20110616git.fc14
           Downgraded By: 1:kde-plasma-networkmanagement-0.9-0.25.20100920.fc14.x86_64 (fedora)
               kde-plasma-networkmanagement = 1:0.9-0.25.20100920.fc14
 You could try using --skip-broken to work around the problem
 You could try running: rpm -Va --nofiles --nodigest

Comment 1 Maciej Sitarz 2011-07-28 13:37:41 UTC
Downgrade didn't work, so I tried updating to latest packages from updates-testing repository.

I installed this packages:
Jul 28 15:12:41 Updated: 1:NetworkManager-glib-0.8.4-2.git20110622.fc14.x86_64
Jul 28 15:12:45 Updated: ModemManager-0.4.998-1.git20110706.fc14.x86_64
Jul 28 15:12:49 Updated: 1:NetworkManager-0.8.4-2.git20110622.fc14.x86_64
Jul 28 15:13:06 Updated: 1:NetworkManager-gnome-0.8.4-2.git20110622.fc14.x86_64

I rebooted the OS just to be sure, but still the connection doesn't work.
I also removed and created again the mobile broadband profile, but no luck.

Comment 2 Maciej Sitarz 2011-07-28 14:18:51 UTC
Created attachment 515730 [details]
NetworkManager debug log

Comment 3 Maciej Sitarz 2011-07-28 14:19:28 UTC
Created attachment 515731 [details]
modem-manager debug log

Comment 4 Jirka Klimes 2011-07-28 15:43:05 UTC
Looks like an interaction issue between NM, MM and kde-plasma-networkmanagement in enabling the modem.

See:
- kde bug: https://bugs.kde.org/show_bug.cgi?id=278231
- kde fix: https://projects.kde.org/projects/extragear/base/networkmanagement/repository/revisions/60acf6a47bacf9e758e23d2fe51ab7e83ef61159

Comment 5 Maciej Sitarz 2011-07-28 17:23:36 UTC
This seems to be the same issue as in the kde bug/fix link provided.

I tried the workaround provided in the kde report (enabling "Connect Automatically" for the Mobile Broadband connection) and it works.
I think we can assume that's the same issue and it's fixed upstream.

Jirka, thanks for help.