Bug 596011

Summary: Regression: total failure to connect via mobile Broadband (cdc_acm)
Product: [Fedora] Fedora Reporter: David Anderson <fedora-packaging2>
Component: NetworkManagerAssignee: Dan Williams <dcbw>
Status: CLOSED CURRENTRELEASE QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: medium Docs Contact:
Priority: low    
Version: 12CC: dcbw, stuart
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: 2010-08-04 05:11: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:
Attachments:
Description Flags
modem manager log
none
network manager log to go with modem-manager log none

Description David Anderson 2010-05-26 06:30:56 UTC
Description of problem:

I upgraded NetworkManager to NetworkManager-0.8.0-6.git20100408.fc12.x86_64, and the corresponding NetworkManager-gnome and NetworkManager-glib versions.

After doing so, attempts to connect to 3G broadband via two different Nokias always failed. On down-grading back to the original versions I had (NetworkManager-0.7.997-2.git20091214.fc12.x86_64), everything worked again.

This is with ModemManager-0.3-2.git20100211.fc12.x86_64, which was upgraded to ModemManager-0.3-9.git20100409.fc12.x86_64 and then downgraded again. ppp version is ppp-2.4.5-2.fc12.x86_64.

How reproducible: Every time.

Here is the log output of the phone being connected, and then the failure to connect to the Internet:

May 25 18:16:39 localhost kernel: usb 1-7: new high speed USB device using ehci_hcd and address 4
May 25 18:16:39 localhost kernel: usb 1-7: New USB device found, idVendor=0421, idProduct=010e
May 25 18:16:39 localhost kernel: usb 1-7: New USB device strings: Mfr=1, Product=2, SerialNumber=3
May 25 18:16:39 localhost kernel: usb 1-7: Product: Nokia E75
May 25 18:16:39 localhost kernel: usb 1-7: Manufacturer: Nokia
May 25 18:16:39 localhost kernel: usb 1-7: SerialNumber: 359557011527518
May 25 18:16:39 localhost kernel: usb 1-7: configuration #1 chosen from 1 choice
May 25 18:16:40 localhost kernel: NET: Registered protocol family 35
May 25 18:16:40 localhost kernel: cdc_acm 1-7:1.1: ttyACM0: USB ACM device
May 25 18:16:40 localhost kernel: usbcore: registered new interface driver cdc_acm
May 25 18:16:40 localhost kernel: cdc_acm: v0.26:USB Abstract Control Model driver for USB modems and ISDN adapters
May 25 18:16:40 localhost kernel: usbcore: registered new interface driver cdc_ether
May 25 18:16:40 localhost kernel: usb 1-7: bad CDC descriptors
May 25 18:16:40 localhost kernel: usbcore: registered new interface driver rndis_host
May 25 18:16:40 localhost kernel: cdc_phonet: probe of 1-7:1.10 failed with error -22
May 25 18:16:40 localhost kernel: usbcore: registered new interface driver cdc_phonet
May 25 18:16:40 localhost kernel: usb 1-7: bad CDC descriptors
May 25 18:16:40 localhost kernel: usbcore: registered new interface driver rndis_wlan
May 25 18:16:40 localhost modem-manager: (ttyACM0) opening serial device...
May 25 18:16:41 localhost modem-manager: (ttyACM0) closing serial device...
May 25 18:16:41 localhost modem-manager: (ttyACM0) opening serial device...
May 25 18:16:41 localhost modem-manager: (Nokia): GSM modem /sys/devices/pci0000:00/0000:00:13.5/usb1/1-7 claimed port ttyACM0
May 25 18:16:41 localhost modem-manager: (ttyACM0) closing serial device...
May 25 18:16:41 localhost NetworkManager: <info> (ttyACM0): new GSM device (driver: 'cdc_acm')
May 25 18:16:41 localhost NetworkManager: <info> (ttyACM0): exported as /org/freedesktop/NetworkManager/Devices/2
May 25 18:16:41 localhost NetworkManager: <info> (ttyACM0): now managed
May 25 18:16:41 localhost NetworkManager: <info> (ttyACM0): device state change: 1 -> 2 (reason 2)
May 25 18:16:41 localhost NetworkManager: <info> (ttyACM0): deactivating device (reason: 2).
May 25 18:16:41 localhost NetworkManager: <info> (ttyACM0): device state change: 2 -> 3 (reason 0)
May 25 18:16:45 localhost NetworkManager: <info> Activation (ttyACM0) starting connection 'Auto Mobile Broadband (GSM) connection'
May 25 18:16:45 localhost NetworkManager: <info> (ttyACM0): device state change: 3 -> 4 (reason 0)
May 25 18:16:45 localhost NetworkManager: <info> Activation (ttyACM0) Stage 1 of 5 (Device Prepare) scheduled...
May 25 18:16:45 localhost NetworkManager: <info> Activation (ttyACM0) Stage 1 of 5 (Device Prepare) started...
May 25 18:16:45 localhost modem-manager: (ttyACM0) opening serial device...
May 25 18:16:45 localhost NetworkManager: <info> Activation (ttyACM0) Stage 1 of 5 (Device Prepare) complete.
May 25 18:16:45 localhost modem-manager: Modem /org/freedesktop/ModemManager/Modems/0: state changed (disabled -> enabling)
May 25 18:16:46 localhost modem-manager: Modem /org/freedesktop/ModemManager/Modems/0: state changed (enabling -> enabled)
May 25 18:16:46 localhost modem-manager: Modem /org/freedesktop/ModemManager/Modems/0: state changed (enabled -> registered)
May 25 18:16:46 localhost modem-manager: Modem /org/freedesktop/ModemManager/Modems/0: state changed (registered -> connecting)
May 25 18:16:46 localhost modem-manager: Modem /org/freedesktop/ModemManager/Modems/0: state changed (connecting -> registered)
May 25 18:16:46 localhost NetworkManager: <info> (ttyACM0): device state change: 4 -> 9 (reason 1)
May 25 18:16:46 localhost NetworkManager: <info> Marking connection 'Auto Mobile Broadband (GSM) connection' invalid.
May 25 18:16:46 localhost NetworkManager: <info> (ttyACM0): device state change: 9 -> 3 (reason 0)
May 25 18:16:46 localhost NetworkManager: <info> (ttyACM0): deactivating device (reason: 0).

Comment 1 Dan Williams 2010-05-26 09:47:05 UTC
Can you do the following for me, as root?

1) install latest ModemManager and NetworkManager
2) service NetworkManager stop
3) killall -TERM modem-manager
4) modem-manager --debug
5) (in another terminal) /usr/sbin/NetworkManager --no-daemon

and then reproduce the problem.  Please then attach the output of both NetworkManager and modem-manager so we can diagnose further.

FWIW this would appear to be limited to Nokia devices via USB, as the following phones work for me tethered via USB:

1) LG Rumor (CDMA)
2) Sony-Ericsson TM-506

and via DUN:

1) Nokia 2726

Comment 2 Stuart D Gathman 2010-08-01 22:26:49 UTC
I have a Cricket A600, which was working perfectly until mid June.  I believe the update that broke it was:

Jun 17 21:38:27 Updated: 1:NetworkManager-glib-0.8.1-0.1.git20100510.fc12.i686
Jun 17 21:39:38 Updated: ModemManager-0.3-13.git20100507.fc12.i686
Jun 17 21:39:43 Updated: 1:NetworkManager-0.8.1-0.1.git20100510.fc12.i686
Jun 17 21:40:24 Updated: 1:NetworkManager-gnome-0.8.1-0.1.git20100510.fc12.i686
Jun 17 21:40:27 Updated: 1:NetworkManager-vpnc-0.8.0-1.git20100411.fc12.i686
Jun 17 21:40:29 Updated: 1:NetworkManager-pptp-0.8.0-1.git20100411.fc12.i686

I am updating to latest to provide the debug info you requested (but for A600, not Nokia).

Comment 3 Stuart D Gathman 2010-08-01 22:48:29 UTC
Created attachment 435921 [details]
modem manager log

Updated from updates-testing

  Updating       : 1:NetworkManager-glib-0.8.1-1.fc12.i686                  1/8 
  Updating       : ModemManager-0.4-4.git20100720.fc12.i686                 2/8 
  Updating       : 1:NetworkManager-0.8.1-1.fc12.i686                       3/8 
  Updating       : 1:NetworkManager-gnome-0.8.1-1.fc12.i686                 4/8 

after initial no-carrier, unplugged and plugged modem.

Comment 4 Stuart D Gathman 2010-08-01 22:49:19 UTC
Created attachment 435922 [details]
network manager log to go with modem-manager log

Comment 5 Stuart D Gathman 2010-08-02 22:23:02 UTC
Since the "no carrier" error seems suspicious, just to make sure, I attached the modem to a Windows box.  The Windows software now asks for a username and password (which it never did before).  So something has changed on the service.  Will report after talking with tech support (who will only talk to you if you run their Windows software).

Comment 6 Stuart D Gathman 2010-08-03 20:05:46 UTC
Ok, the current failure is because the Cricket autopay failed for July (suspending the account).  That still doesn't explain why it quit working mid June.  However, it does mean that the logs I uploaded are worthless, and maybe I should delete them.  (Or maybe NM can reliably detect a suspended account.)

As soon as we get done yelling at their billing dept, I'll test again with the latest NM to see if the problem from the June update is fixed.

Comment 7 Stuart D Gathman 2010-08-04 03:12:35 UTC
Whatever the problem was Jun 17, it is now resolved with the latest NM from updates (writing this via modem).  Unless developers request it, I won't bother downgrading to narrow down exactly which version was broken.  Sorry for the noise.

Comment 8 Dan Williams 2010-08-04 05:11:22 UTC
No problem, thanks for the update.