Modem suddenly disconnecting?

Fri Dec 6 02:09:29 PST 2013

Hi I'm using modemmanager-0.4 and I've got a problem trying to use my integrated HP broadband modem.

Here the logs and a description of the problem:

ModemManager and NetworkManager detect my modem OK.

Dec 06 10:43:09 [modem-manager] (ttyUSB0) closing serial device...
Dec 06 10:43:09 [modem-manager] (ttyUSB0) opening serial device...
Dec 06 10:43:12 [modem-manager] (ttyUSB0) closing serial device...
Dec 06 10:43:12 [NetworkManager] <warn> (ttyUSB1): failed to look up interface index
Dec 06 10:43:12 [NetworkManager] <info> (ttyUSB1): new GSM device (driver: 'qcserial' ifindex: -1)
Dec 06 10:43:12 [NetworkManager] <info> (ttyUSB1): exported as /org/freedesktop/NetworkManager/Devices/2
Dec 06 10:43:12 [NetworkManager] <info> (ttyUSB1): now managed
Dec 06 10:43:12 [NetworkManager] <info> (ttyUSB1): device state change: 1 -> 2 (reason 2)
Dec 06 10:43:12 [NetworkManager] <info> (ttyUSB1): deactivating device (reason: 2).
Dec 06 10:43:12 [NetworkManager] <info> (ttyUSB1): device state change: 2 -> 3 (reason 0)
Dec 06 10:43:54 [modem-manager] (ttyUSB1) opening serial device...
Dec 06 10:43:54 [modem-manager] Modem /org/freedesktop/ModemManager/Modems/0: unlock no longer required
Dec 06 10:43:54 [modem-manager] (ttyUSB1) closing serial device...
Dec 06 10:43:54 [modem-manager] (ttyUSB1) opening serial device...
Dec 06 10:43:54 [modem-manager] Modem /org/freedesktop/ModemManager/Modems/0: state changed (disabled -> enabling)
Dec 06 10:43:54 [modem-manager] Modem /org/freedesktop/ModemManager/Modems/0: state changed (enabling -> enabled)
Dec 06 10:43:54 [NetworkManager] <info> WWAN now enabled by management service

At this point I have programmatically enabled and unlocked the modem by sending sendPin() and enable() to the modem via DBUS.
But then, suddenly I get a disconnect from the USB modem. I don't understand why this happens, and I don't do anything programmatically here other than requesting modem information (manufacturer, network registration).

Dec 06 10:43:58 [modem-manager] (ttyUSB1) closing serial device...
Dec 06 10:43:58 [kernel] [   90.892492] usb 1-1.2: USB disconnect, device number 4
Dec 06 10:43:58 [kernel] [   90.892658] qcserial ttyUSB0: Qualcomm USB modem converter now disconnected from ttyUSB0
Dec 06 10:43:58 [kernel] [   90.892676] qcserial 1-1.2:1.1: device disconnected
Dec 06 10:43:58 [kernel] [   90.892807] qcserial ttyUSB1: Qualcomm USB modem converter now disconnected from ttyUSB1
Dec 06 10:43:58 [kernel] [   90.892819] qcserial 1-1.2:1.2: device disconnected
Dec 06 10:43:58 [modem-manager] Modem /org/freedesktop/ModemManager/Modems/0: state changed (enabled -> disabled)
Dec 06 10:43:58 [NetworkManager] <info> (ttyUSB1): now unmanaged
Dec 06 10:43:58 [NetworkManager] <info> (ttyUSB1): device state change: 3 -> 1 (reason 36)
Dec 06 10:43:58 [NetworkManager] <info> (ttyUSB1): cleaning up...
Dec 06 10:43:58 [NetworkManager] <info> (ttyUSB1): taking down device.

At this point the modem is down and disappeared from ModemManager.
Then it shows up again as a new USB device.

Dec 06 10:43:59 [kernel] [   91.323911] usb 1-1.2: new high-speed USB device number 8 using ehci_hcd
Dec 06 10:43:59 [kernel] [   91.412677] usb 1-1.2: config 1 has an invalid interface number: 1 but max is 0
Dec 06 10:43:59 [kernel] [   91.412683] usb 1-1.2: config 1 has no interface number 0
Dec 06 10:43:59 [kernel] [   91.414620] usb 1-1.2: New USB device found, idVendor=03f0, idProduct=241d
Dec 06 10:43:59 [kernel] [   91.414626] usb 1-1.2: New USB device strings: Mfr=3, Product=2, SerialNumber=0
Dec 06 10:43:59 [kernel] [   91.414630] usb 1-1.2: Product: HP un2420 Mobile Broadband Module
Dec 06 10:43:59 [kernel] [   91.414634] usb 1-1.2: Manufacturer: Qualcomm Incorporated
Dec 06 10:43:59 [kernel] [   91.416325] qcserial 1-1.2:1.1: Qualcomm USB modem converter detected
Dec 06 10:43:59 [kernel] [   91.416443] usb 1-1.2: Qualcomm USB modem converter now attached to ttyUSB0
Dec 06 10:44:00 [modem-manager] (ttyUSB0) opening serial device...
Dec 06 10:44:04 [modem-manager] (ttyUSB0) closing serial device...
Dec 06 10:44:04 [kernel] [   96.254729] usb 1-1.2: USB disconnect, device number 8
Dec 06 10:44:04 [kernel] [   96.254856] qcserial ttyUSB0: Qualcomm USB modem converter now disconnected from ttyUSB0
Dec 06 10:44:04 [kernel] [   96.254873] qcserial 1-1.2:1.1: device disconnected
Dec 06 10:44:04 [modem-manager] mm_serial_port_close: assertion `priv->open_count > 0' failed
Dec 06 10:44:04 [kernel] [   96.431980] usb 1-1.2: new high-speed USB device number 9 using ehci_hcd
Dec 06 10:44:04 [kernel] [   96.529939] usb 1-1.2: New USB device found, idVendor=03f0, idProduct=251d
Dec 06 10:44:04 [kernel] [   96.529945] usb 1-1.2: New USB device strings: Mfr=4, Product=3, SerialNumber=0
Dec 06 10:44:04 [kernel] [   96.529949] usb 1-1.2: Product: HP un2420 Mobile Broadband Module
Dec 06 10:44:04 [kernel] [   96.529953] usb 1-1.2: Manufacturer: Qualcomm Incorporated
Dec 06 10:44:04 [kernel] [   96.534212] qcserial 1-1.2:1.1: Qualcomm USB modem converter detected
Dec 06 10:44:04 [kernel] [   96.534294] usb 1-1.2: Qualcomm USB modem converter now attached to ttyUSB0
Dec 06 10:44:04 [kernel] [   96.535342] qcserial 1-1.2:1.2: Qualcomm USB modem converter detected
Dec 06 10:44:04 [kernel] [   96.535419] usb 1-1.2: Qualcomm USB modem converter now attached to ttyUSB1

Here ModemManager then detects a new device (the same modem!!) and registeres as a new modem device under a different DBUS path than previously (even though still the same device).

Dec 06 10:44:04 [modem-manager] (ttyUSB0) opening serial device...
Dec 06 10:44:04 [modem-manager] (ttyUSB1) opening serial device...
Dec 06 10:44:08 [modem-manager] (ttyUSB1) closing serial device...
Dec 06 10:44:08 [modem-manager] (ttyUSB1) opening serial device...
Dec 06 10:44:08 [modem-manager] (Gobi): GSM modem /sys/devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.2 claimed port ttyUSB1
Dec 06 10:44:08 [modem-manager] (ttyUSB1) closing serial device...
Dec 06 10:44:17 [modem-manager] (ttyUSB0) closing serial device...
Dec 06 10:44:17 [modem-manager] (ttyUSB0) opening serial device...
Dec 06 10:44:20 [modem-manager] (ttyUSB0) closing serial device...
Dec 06 10:44:20 [NetworkManager] <warn> (ttyUSB1): failed to look up interface index
Dec 06 10:44:20 [NetworkManager] <info> WWAN now disabled by management service
Dec 06 10:44:20 [NetworkManager] <info> (ttyUSB1): new GSM device (driver: 'qcserial' ifindex: -1)
Dec 06 10:44:20 [NetworkManager] <info> (ttyUSB1): exported as /org/freedesktop/NetworkManager/Devices/3
Dec 06 10:44:20 [NetworkManager] <info> (ttyUSB1): now managed
Dec 06 10:44:20 [NetworkManager] <info> (ttyUSB1): device state change: 1 -> 2 (reason 2)
Dec 06 10:44:20 [NetworkManager] <info> (ttyUSB1): deactivating device (reason: 2).
Dec 06 10:44:20 [NetworkManager] <info> (ttyUSB1): device state change: 2 -> 3 (reason 0)

Anyone got any idea why this happens and how I can further debug the problem?

Thanks,
Karoline
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freedesktop.org/archives/modemmanager-devel/attachments/20131206/ba7f1afd/attachment.html>