Bug 14499 - USB serial regression after 2.6.31.1 with Huawei E220 GSM modem
Summary: USB serial regression after 2.6.31.1 with Huawei E220 GSM modem
Status: CLOSED INVALID
Alias: None
Product: Drivers
Classification: Unclassified
Component: USB (show other bugs)
Hardware: All Linux
: P1 normal
Assignee: Alan Stern
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2009-10-28 14:32 UTC by Iiro Rinta-Jouppi
Modified: 2011-07-10 14:30 UTC (History)
9 users (show)

See Also:
Kernel Version: 2.6.31.2 ... 2.6.31-5
Subsystem:
Regression: Yes
Bisected commit-id:


Attachments
last known working kernel with E220 (3.51 KB, text/plain)
2009-10-28 14:32 UTC, Iiro Rinta-Jouppi
Details
2.6.31.5 E220 going on/off/on/off (5.56 KB, text/plain)
2009-10-28 14:34 UTC, Iiro Rinta-Jouppi
Details
got 2.6.31.5 working with rmmod usb_storage (2.62 KB, text/plain)
2009-10-28 14:35 UTC, Iiro Rinta-Jouppi
Details
usbmon log file (110.64 KB, text/plain)
2010-05-14 01:49 UTC, Frederic MASSOT
Details
dmesg from 2.6.39.2 with Huawei E1823 (99.49 KB, text/plain)
2011-07-10 14:27 UTC, Martin Mokrejs
Details
Huawei1823-2.6.39.2.usbmon.log (38.20 KB, text/plain)
2011-07-10 14:28 UTC, Martin Mokrejs
Details
once it got briefly enough power - Huawei E1823 on 2.6.39.2 (10.07 KB, text/plain)
2011-07-10 14:30 UTC, Martin Mokrejs
Details

Description Iiro Rinta-Jouppi 2009-10-28 14:32:49 UTC
Created attachment 23558 [details]
last known working kernel with E220

2.6.31-11 Ubuntu kernel (=2.6.31.1) works directly without a glitch with Huawei E220 3G USB dongle.
Ubuntu kernels -12, -13, -14 and plain 2.6.31.5 kernel does not work directly. It does not work either after several plug in / out cycles.

Three logs attached
1. Ubuntu 2.6.31-11 kernel. USB dongle inserted and Network manager connection selected. Fully working internet connection.

2. 2.6.31.5 from http://kernel.ubuntu.com/~kernel-ppa/mainline/v2.6.31.5/ USB inserted and after Network manager I waited couple of cycles of automatic removal of the driver.

3. 2.6.31.5 from http://kernel.ubuntu.com/~kernel-ppa/mainline/v2.6.31.5/ USB inserted and commands:
    sudo rmmod usb-storage
    sudo modprobe usbserial vendor=0x12d1 product=0x1003
after selecting the right connection from Network Manager it starts to work. This method does not work always.
Comment 1 Iiro Rinta-Jouppi 2009-10-28 14:34:30 UTC
Created attachment 23559 [details]
2.6.31.5 E220 going on/off/on/off
Comment 2 Iiro Rinta-Jouppi 2009-10-28 14:35:54 UTC
Created attachment 23560 [details]
got 2.6.31.5 working with rmmod usb_storage
Comment 3 Greg Kroah-Hartman 2009-10-28 15:28:08 UTC
This is fixed in 2.6.31.6.
Comment 4 Benjamin Herrenschmidt 2009-11-02 09:44:17 UTC
Hi Greg !

Do you have a pointer to the patch ? I couldn't find it ... my patch in .5 that fixes E169 doesn't seem to fix E220/E620 according to some ubuntu user reports.
Comment 5 Pedro Cirne 2009-11-02 10:03:36 UTC
Same issue with E220:

[ 4060.068051] usb 3-1: new full speed USB device using uhci_hcd and address 22
[ 4060.230258] usb 3-1: configuration #1 chosen from 1 choice
[ 4060.237777] scsi134 : SCSI emulation for USB Mass Storage devices
[ 4060.238017] usb-storage: device found at 22
[ 4060.238022] usb-storage: waiting for device to settle before scanning
[ 4060.424127] usb 3-1: USB disconnect, address 22
[ 4061.160061] usb 3-1: new full speed USB device using uhci_hcd and address 23
[ 4061.323258] usb 3-1: configuration #1 chosen from 1 choice
[ 4061.330765] option 3-1:1.0: GSM modem (1-port) converter detected
[ 4061.330850] usb 3-1: GSM modem (1-port) converter now attached to ttyUSB0
[ 4061.333206] option 3-1:1.1: GSM modem (1-port) converter detected
[ 4061.333274] usb 3-1: GSM modem (1-port) converter now attached to ttyUSB1
[ 4061.339421] scsi137 : SCSI emulation for USB Mass Storage devices
[ 4061.351221] usb-storage: device found at 23
[ 4061.351225] usb-storage: waiting for device to settle before scanning
[ 4066.350149] usb-storage: device scan complete
[ 4066.354135] scsi 137:0:0:0: CD-ROM HUAWEI Mass Storage 2.31 PQ: 0 ANSI: 2
[ 4066.383094] sr1: scsi-1 drive
[ 4066.383346] sr 137:0:0:0: Attached scsi CD-ROM sr1
[ 4066.383494] sr 137:0:0:0: Attached scsi generic sg2 type 5
[ 4077.753095] sr1: CDROM (ioctl) error, command: Get configuration 46 00 00 00 00 00 00 00 20 00
[ 4077.753122] sr: Sense Key : No Sense [current]
[ 4077.753131] sr: Add. Sense: No additional sense information
[ 4078.016109] sr1: CDROM (ioctl) error, command: Get configuration 46 00 00 00 00 00 00 00 20 00
[ 4078.016137] sr: Sense Key : No Sense [current]
[ 4078.016146] sr: Add. Sense: No additional sense information
[ 4078.155063] option: option_instat_callback: error -108
[ 4078.156301] option1 ttyUSB0: GSM modem (1-port) converter now disconnected from ttyUSB0
[ 4078.156324] option 3-1:1.0: device disconnected
[ 4078.156388] option1 ttyUSB1: GSM modem (1-port) converter now disconnected from ttyUSB1
[ 4078.156405] option 3-1:1.1: device disconnected
[ 4078.324045] usb 3-1: reset full speed USB device using uhci_hcd and address 23
[ 4078.471254] option 3-1:1.1: GSM modem (1-port) converter detected
[ 4078.471417] usb 3-1: GSM modem (1-port) converter now attached to ttyUSB0
[ 4078.479115] option 3-1:1.0: GSM modem (1-port) converter detected
[ 4078.479276] usb 3-1: GSM modem (1-port) converter now attached to ttyUSB1
[ 4078.876079] option: option_instat_callback: error -108
[ 4078.877639] option1 ttyUSB1: GSM modem (1-port) converter now disconnected from ttyUSB1
[ 4078.877683] option 3-1:1.0: device disconnected
[ 4078.877796] option1 ttyUSB0: GSM modem (1-port) converter now disconnected from ttyUSB0
[ 4078.877827] option 3-1:1.1: device disconnected
[ 4079.000069] usb 3-1: reset full speed USB device using uhci_hcd and address 23
[ 4079.124035] usb 3-1: device descriptor read/64, error -71
[ 4079.296744] usb 3-1: USB disconnect, address 23

cirne@cirne-laptop:/var/log$ lsusb
Bus 002 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 003 Device 026: ID 12d1:1003 Huawei Technologies Co., Ltd. E220 HSDPA Modem / E270 HSDPA/HSUPA Modem
Bus 003 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 004 Device 002: ID 044e:300c Alps Electric Co., Ltd Bluetooth Controller (ALPS/UGPZ6)
Bus 004 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 005 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
cirne@cirne-laptop:/var/log$ uname -a
Linux cirne-laptop 2.6.31-14-generic #48-Ubuntu SMP Fri Oct 16 14:04:26 UTC 2009 i686 GNU/Linux

Where can we find a patch/fix for this? :)
Comment 6 Iiro Rinta-Jouppi 2009-11-03 22:51:19 UTC
I can just confirm what Benjamin wrote in #4. The fix that got into 2.6.31.5 did not fix the E220 issue. As you can see from the logs I attached, the 2.6.31.1 was the last known working kernel for E220. The USB patch that got in 2.6.31.2 broke things and they still are not fixed in 2.6.31.5. I have tested it with other kernels in between, and they do not work either.

I'll wait for 2.6.31.6...

/Iiro
Comment 7 Alan Stern 2009-11-07 02:43:20 UTC
None of the usbmon traces in the three attachments show anything useful because they monitored the wrong bus: They looked at bus 1 whereas the E220 device was on bus 3.  Can we get another set of traces?
Comment 8 Benjamin Herrenschmidt 2009-11-07 03:04:25 UTC
Iiro, please do a log using the "0u" file which will capture everything,
that's the easiest way to avoid that sort of confusion :-)
Comment 9 Iiro Rinta-Jouppi 2009-11-07 14:21:28 UTC
Damn, I'm really sorry for the confusion. It seems that I was not careful enough. At the moment I am in another country than my E220, so unfortunately I can not test it further in couple of weeks.
Comment 10 Benjamin Herrenschmidt 2009-11-07 21:51:54 UTC
Ok so the launchpad bug https://bugs.launchpad.net/bugs/446146 has some more logs now. Specifically:

http://launchpadlibrarian.net/35317354/dmesg-apw5.bz2
http://launchpadlibrarian.net/35317459/usbmon-apw5.bz2

should be logs done with ubuntu variant of 2.6.31.5 which shows the problem with the E220.
Comment 11 Alan Stern 2009-11-08 04:53:13 UTC
This log shows a very different problem from before.  To begin with, the E220's mass-storage interface declares itself as a cdrom instead of a disk drive.

The host sends a command code 0x46, which the device doesn't understand.  (I'm not too familiar with SCSI cdrom commands; according to the dmesg log 0x46 is GET CONFIGURATION.)   Instead of telling the host it doesn't understand the command, which would be the right thing to do, the device replies with a failure indication and no sense data.  That's what causes those ioctl error messages in the log.

Then the host sends a MODE SENSE(10) command (0x5a) which the device apparently thinks it understands, but in fact it doesn't.  Its reply is too long, leading the host to reset the device.  This reset confuses the device and causes it to disconnect itself from the bus.  That's the reason for all those disconnections.

I don't know what is the source of these two commands.  I suspect it is a user program rather than the kernel's CD driver, but this is just a guess.  It might udev, hal, or even usb_modeswitch.  Whichever it is, if the program can be prevented from sending these commands to the device then the problem should go away.

Alternatively, maybe Huawei can provide a firmware update to fix these two issues, if somebody informs them about the problem.
Comment 12 Benjamin Herrenschmidt 2009-11-08 07:04:41 UTC
I have some doubts as to relying on a FW update from Huawei...

I wonder what's the best approach to work around those. We could add more tweaks to the driver to make it more robust for things like mode sense(10) but I'm hesitant to put too many hacks that could potentially make it miss real errors.

Or we could just blacklist the E220 from usb storage... we still want the magic quirk in initializers.c to run but it could be made to return an error.

Now, of course, an additional problem is that I suspect a lot of those Huawei devices have the nasty habit of having the same vendorID/deviceID... we we may end up also black listing good ones which means losing the usage of the SD-card reader on them, but that's secondary to having the modem functionality I believe.
Comment 13 Benjamin Herrenschmidt 2009-11-08 07:07:25 UTC
I have some doubts as to relying on a FW update from Huawei...

I wonder what's the best approach to work around those. We could add more tweaks to the driver to make it more robust for things like mode sense(10) but I'm hesitant to put too many hacks that could potentially make it miss real errors.

Or we could just blacklist the E220 from usb storage... we still want the magic quirk in initializers.c to run but it could be made to return an error.

Now, of course, an additional problem is that I suspect a lot of those Huawei devices have the nasty habit of having the same vendorID/deviceID... we we may end up also black listing good ones which means losing the usage of the SD-card reader on them, but that's secondary to having the modem functionality I believe.
Comment 14 Benjamin Herrenschmidt 2009-11-08 07:10:22 UTC
James, I added you on CC as SCSI maintainer. The problem we have here is that those SCSI protocol "bugs" in the modem are causing the SCSI stack to send host resets which we then turn into USB resets, which have the effect of disrupting the modem side of the device as well, essentially preventing it from working.

It looks like a lot of those Huawei things have differently broken mass storage firmware (see the E169 with its incorrect sense length), but this one seems to be a bit more nasty.

Should we ignore incorrect length (or add a quirk for that specific value of incorrect length ?) on mode sense (10) as a workaround ? Or something else ? I like avoiding device specific quirks (ie, I prefer making the code generally more robust to deal with that sort of issues which is how we fixed the other sense issues of the E169 models) but this looks a bit "edgy".
Comment 15 Benjamin Herrenschmidt 2009-11-08 07:20:22 UTC
Actually, James, I wonder ... should we create a new error policy for that sort of device (maybe triggered by usb-storage in general or by usb-storage when faced with a multi-function device, or even via a quirk list) that simply avoids resets on such errors ? IE, just error out the command, but don't reset the device...

What do you think ?
Comment 16 Alan Stern 2009-11-08 15:47:38 UTC
The resets in question aren't initiated by the SCSI core.  They come directly from usb-storage; it always resets a device when certain types of protocol violation occur.

Oliver Neukum has suggested adding a USB quirks flag to mark devices which should not be reset during error recovery.  In theory this would help.  It would leave the modem's mass-storage interface unusable, but that's no worse than it is right now.  Alternatively, instead of blacklisting all the Huawei modems from usb-storage, we could reject just the devices which present as cdrom drives.

In the end, it really would be best to update the firmware.  I don't know why Huawei has so much trouble obeying the restrictions of the USB mass-storage protocol.
Comment 17 Benjamin Herrenschmidt 2009-11-08 20:32:08 UTC
Why not doing the reset in this case would make usb-storage unuseable ? In the above case, can't we just return some kind of transport error to the initiator in user space and move on ? IE. The kernel CD-ROM driver would probably still work.
Comment 18 Alan Stern 2009-11-08 23:34:15 UTC
We can (and do) return a transport error to the initiator.  But without the reset we can't move on -- the protocol violation means that we have lost proper framing and so we can't communicate with the device.  Thus it is unusable.

In theory, we could restore proper framing by polling the device repeatedly and waiting until it stops sending data.  This would be clumsy and time consuming, but it might sometimes work.  Maybe.
Comment 19 Benjamin Herrenschmidt 2009-11-08 23:38:09 UTC
Hrm... that sucks... We can also try a quirk to blacklist those two commands (especially the MODE_SENSE(10) I suppose...)
Comment 20 Alan Stern 2009-11-09 02:34:32 UTC
And then what about the next device, which will mess up on a different set of commands?  And the device after that?  This way madness lies...

I still think there's a good chance the Huawei people can fix their firmware.  They've done it before.
Comment 21 Benjamin Herrenschmidt 2009-11-09 03:36:16 UTC
Yeah, possibly. But in the meantime, we still have a regression on our hands and quite a lot of users who cannot use their modems anymore. My attempts at contacting Huawei have not yet been successful.

So what do we do ? We could hack back the initializer for these in USB storage to make probing of storage fail, which would bring us back to the 2.6.31.1 situation I suppose, which means no storage but at least a working modem. Some people would complain that it reverts the support for the micro-SD reader that worked for the E169 and E620 models (the one we fixed with the sense retry patch) but I don't see that as being a big deal.

What do you reckon ?
Comment 22 Alan Stern 2009-11-09 15:15:10 UTC
At the moment I don't see much of an alternative.  If Fangxiao Zhi gets annoyed then maybe he'll be motivated to get the firmware fixed.

I suppose the initializer could send an INQUIRY command to determine whether the device claims to be a hard drive or a cdrom, and make probing succeed for one but not the other.  But that's a brittle sort of heuristic.
Comment 23 Benjamin Herrenschmidt 2009-11-11 00:22:32 UTC
So I got in touch with Franko Fang from Huawei. Unfortunately, he cannot post to this bugzilla entry, but he asked that we provide the FW version of the problematic E220 modems.


 - Boot with a kernel where the modem works (ie, you -do- get a /dev/ttyUSB0 created)
 - open it with minicom
 - type the AT command "ati" <return>
 - tell us the modem response

For example, my E169 says:

ati                                                                                
Manufacturer: huawei                                                         
Model: E169                                                                  
Revision: 11.314.17.00.261              
IMEI: 358109021939159                   
+GCAP: +CGSM,+DS,+ES
Comment 24 Damjan Jovanovic 2009-11-12 04:08:30 UTC
My affected Huawei E220 says this:

Manufacturer: huawei
Model: E220
Revision: 11.110.05.00.00
IMEI: 358191017694576
+GCAP: +CGSM,+DS,+ES

The question is: how does Windows probe it so it never breaks?
Comment 25 Arto Jarvinen 2009-11-13 08:31:53 UTC
Manufacturer: huawei
Model: E220
Revision: 11.117.09.01.56
IMEI: 358954001901277
+GCAP: +CGSM,+DS,+ES

The network manager always tells me that I get connected but most of the time I don't get a nameserver, like so:

arto@Sectra:~$ cat /etc/resolv.conf
# Generated by NetworkManager

When I unplug and plug in the modem again, I sometimes actually get a nameserver, like this:

arto@Sectra:~$ cat /etc/resolv.conf
# Generated by NetworkManager
nameserver 130.244.127.161
nameserver 130.244.127.169
Comment 26 Damjan Jovanovic 2010-05-03 11:15:59 UTC
This is still present on Ubuntu 10.04 with its 2.6.32 kernel.

The crashes/resets seem to come from user-space interaction with the device, not from something the kernel does automatically. In particular, killing devkit-power daemon and devkit-disks-daemon on Ubuntu 9.10, and killing udisks-daemon on Ubuntu 10.04, stops the crashes.

Blacklisting the E220 from udisks-daemon by adding ENV{UDISKS_DISABLE_POLLING}="1", ENV{UDISKS_PRESENTATION_NOPOLICY}="1" to the udev rule for the E220 (then reboot before testing) seems to work as well.

See https://bugs.launchpad.net/ubuntu/+source/linux/+bug/446146/comments/260 and https://bugs.launchpad.net/ubuntu/+source/linux/+bug/449394/comments/68 for more details.

Can someone else test these workarounds? If they work, maybe this bug should be worked around in user-space.
Comment 27 Alan Stern 2010-05-03 15:19:22 UTC
On Mon, 3 May 2010 bugzilla-daemon@bugzilla.kernel.org wrote:

> The crashes/resets seem to come from user-space interaction with the device,
> not from something the kernel does automatically. In particular, killing
> devkit-power daemon and devkit-disks-daemon on Ubuntu 9.10, and killing
> udisks-daemon on Ubuntu 10.04, stops the crashes.

It would help to know exactly what causes the device to fail.  You 
wrote that running "udisks --enumerate" is enough to do it.  Can you 
capture a usbmon trace showing this, and attach it to this bug report?

If this allows us to identify a flaw in the Huawei firmware, the 
manufacturer may be able to fix it with a firmware update.

Alan Stern
Comment 28 Frederic MASSOT 2010-05-09 15:15:35 UTC
Hi,

I have the same connection problem, since some months I can not connect to the Internet with Gnome and NetworkManager, I use LXDE and NetworkManager.

I opened several bug report in Debian, Linux and Gnome:

http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=563551

https://bugzilla.kernel.org/show_bug.cgi?id=15650

https://bugzilla.gnome.org/show_bug.cgi?id=617454

Others are the same problem:

http://www.draisberghof.de/usb_modeswitch/bb/viewtopic.php?p=2036#2036


I tested the method of Damjan Jovanovic by killing devkit-disks-daemon (Debian package devicekit-disks 009-3).

Below the logs before killing devkit-disks-daemon, the connection fails:

May  9 16:48:18 cthulhu kernel: usb 5-2: new full speed USB device using uhci_hcd and address 5
May  9 16:48:19 cthulhu kernel: usb 5-2: New USB device found, idVendor=12d1, idProduct=1003
May  9 16:48:19 cthulhu kernel: usb 5-2: New USB device strings: Mfr=1, Product=2, SerialNumber=0
May  9 16:48:19 cthulhu kernel: usb 5-2: Product: HUAWEI Mobile
May  9 16:48:19 cthulhu kernel: usb 5-2: Manufacturer: HUAWEI Technologies
May  9 16:48:19 cthulhu kernel: scsi12 : usb-storage 5-2:1.0
May  9 16:48:19 cthulhu kernel: usb 5-2: USB disconnect, address 5
May  9 16:48:19 cthulhu kernel: usb 5-2: new full speed USB device using uhci_hcd and address 6
May  9 16:48:19 cthulhu kernel: usb 5-2: New USB device found, idVendor=12d1, idProduct=1003
May  9 16:48:19 cthulhu kernel: usb 5-2: New USB device strings: Mfr=1, Product=2, SerialNumber=0
May  9 16:48:19 cthulhu kernel: usb 5-2: Product: HUAWEI Mobile
May  9 16:48:19 cthulhu kernel: usb 5-2: Manufacturer: HUAWEI Technologies
May  9 16:48:19 cthulhu kernel: option 5-2:1.0: GSM modem (1-port) converter detected
May  9 16:48:19 cthulhu kernel: usb 5-2: GSM modem (1-port) converter now attached to ttyUSB0
May  9 16:48:19 cthulhu kernel: option 5-2:1.1: GSM modem (1-port) converter detected
May  9 16:48:19 cthulhu kernel: usb 5-2: GSM modem (1-port) converter now attached to ttyUSB1
May  9 16:48:19 cthulhu kernel: scsi15 : usb-storage 5-2:1.2
May  9 16:48:20 cthulhu modem-manager: (Huawei): (ttyUSB1) deferring support check
May  9 16:48:20 cthulhu modem-manager: (ttyUSB0) opening serial device...
May  9 16:48:20 cthulhu modem-manager: (ttyUSB0): probe requested by plugin 'Huawei'
May  9 16:48:23 cthulhu modem-manager: (ttyUSB1): re-checking support...
May  9 16:48:23 cthulhu modem-manager: (Huawei): (ttyUSB1) deferring support check
May  9 16:48:24 cthulhu kernel: scsi 15:0:0:0: CD-ROM            HUAWEI   Mass Storage     2.31 PQ: 0 ANSI: 2
May  9 16:48:24 cthulhu kernel: sr2: scsi-1 drive
May  9 16:48:24 cthulhu kernel: sr 15:0:0:0: Attached scsi CD-ROM sr2
May  9 16:48:24 cthulhu kernel: sr 15:0:0:0: Attached scsi generic sg3 type 5
May  9 16:48:26 cthulhu modem-manager: (ttyUSB1): re-checking support...
May  9 16:48:26 cthulhu modem-manager: (Huawei): (ttyUSB1) deferring support check
May  9 16:48:29 cthulhu modem-manager: (ttyUSB1): re-checking support...
May  9 16:48:29 cthulhu modem-manager: (Huawei): (ttyUSB1) deferring support check
May  9 16:48:32 cthulhu modem-manager: (ttyUSB1): re-checking support...
May  9 16:48:32 cthulhu modem-manager: (Huawei): (ttyUSB1) deferring support check
May  9 16:48:32 cthulhu modem-manager: (ttyUSB0) closing serial device...
May  9 16:48:32 cthulhu modem-manager: (Huawei): GSM modem /sys/devices/pci0000:00/0000:00:1d.0/usb5/5-2 claimed port ttyUSB0
May  9 16:48:32 cthulhu modem-manager: Added modem /sys/devices/pci0000:00/0000:00:1d.0/usb5/5-2
May  9 16:48:32 cthulhu modem-manager: Exported modem /sys/devices/pci0000:00/0000:00:1d.0/usb5/5-2 as /org/freedesktop/ModemManager/Modems/1
May  9 16:48:32 cthulhu NetworkManager: <info>  (ttyUSB0): new GSM device (driver: 'option1')
May  9 16:48:32 cthulhu NetworkManager: <info>  (ttyUSB0): exported as /org/freedesktop/NetworkManager/Devices/3
May  9 16:48:32 cthulhu NetworkManager: <info>  (ttyUSB0): now managed
May  9 16:48:32 cthulhu NetworkManager: <info>  (ttyUSB0): device state change: 1 -> 2 (reason 2)
May  9 16:48:32 cthulhu NetworkManager: <info>  (ttyUSB0): deactivating device (reason: 2).
May  9 16:48:32 cthulhu NetworkManager: <info>  (ttyUSB0): device state change: 2 -> 3 (reason 0)
May  9 16:48:32 cthulhu NetworkManager: <info>  Activation (ttyUSB0) starting connection 'Connexion GSM SFR'
May  9 16:48:32 cthulhu NetworkManager: <info>  (ttyUSB0): device state change: 3 -> 4 (reason 0)
May  9 16:48:32 cthulhu NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) scheduled...
May  9 16:48:32 cthulhu NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) started...
May  9 16:48:32 cthulhu NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) complete.
May  9 16:48:32 cthulhu modem-manager: (ttyUSB0) opening serial device...
May  9 16:48:32 cthulhu modem-manager: Modem /org/freedesktop/ModemManager/Modems/1: state changed (disabled -> enabling)
May  9 16:48:32 cthulhu modem-manager: Got failure code 11: SIM PIN required
May  9 16:48:32 cthulhu modem-manager: Modem /org/freedesktop/ModemManager/Modems/1: state changed (enabling -> enabled)
May  9 16:48:32 cthulhu modem-manager: Registration state changed: 2
May  9 16:48:32 cthulhu modem-manager: Modem /org/freedesktop/ModemManager/Modems/1: state changed (enabled -> searching)
May  9 16:48:34 cthulhu kernel: sr2: CDROM (ioctl) error, command: cdb[0]=0x51 51 00 00 00 00 00 00 00 02 00
May  9 16:48:34 cthulhu kernel: sr: Sense Key : 0x4 [current] 
May  9 16:48:34 cthulhu kernel: sr: ASC=0x0 ASCQ=0x0
May  9 16:48:34 cthulhu kernel: sr2: CDROM (ioctl) error, command: cdb[0]=0x46 46 00 00 00 00 00 00 00 20 00
May  9 16:48:34 cthulhu kernel: sr: Sense Key : 0x4 [current] 
May  9 16:48:34 cthulhu kernel: sr: ASC=0x0 ASCQ=0x0
May  9 16:48:34 cthulhu kernel: sr2: CDROM (ioctl) error, command: cdb[0]=0x46 46 00 00 00 00 00 00 00 20 00
May  9 16:48:34 cthulhu kernel: sr: Sense Key : 0x4 [current] 
May  9 16:48:34 cthulhu kernel: sr: ASC=0x0 ASCQ=0x0
May  9 16:48:34 cthulhu kernel: sr2: CDROM (ioctl) error, command: cdb[0]=0x46 46 00 00 00 00 00 00 00 20 00
May  9 16:48:34 cthulhu kernel: sr: Sense Key : 0x4 [current] 
May  9 16:48:34 cthulhu kernel: sr: ASC=0x0 ASCQ=0x0
May  9 16:48:34 cthulhu kernel: option: option_instat_callback: error -108
May  9 16:48:34 cthulhu modem-manager: (ttyUSB0) closing serial device...
May  9 16:48:34 cthulhu kernel: option1 ttyUSB0: GSM modem (1-port) converter now disconnected from ttyUSB0
May  9 16:48:34 cthulhu kernel: option 5-2:1.0: device disconnected
May  9 16:48:34 cthulhu kernel: option1 ttyUSB1: GSM modem (1-port) converter now disconnected from ttyUSB1
May  9 16:48:34 cthulhu kernel: option 5-2:1.1: device disconnected
May  9 16:48:34 cthulhu modem-manager: Modem /org/freedesktop/ModemManager/Modems/1: state changed (searching -> disabled)
May  9 16:48:34 cthulhu modem-manager: Removed modem /sys/devices/pci0000:00/0000:00:1d.0/usb5/5-2
May  9 16:48:34 cthulhu modem-manager: mm_callback_info_schedule: assertion `info->pending_id == 0' failed
May  9 16:48:34 cthulhu NetworkManager: <info>  (ttyUSB0): now unmanaged
May  9 16:48:34 cthulhu NetworkManager: <info>  (ttyUSB0): device state change: 4 -> 1 (reason 36)
May  9 16:48:34 cthulhu NetworkManager: <info>  (ttyUSB0): deactivating device (reason: 36).
May  9 16:48:34 cthulhu modem-manager: mm_callback_info_schedule: assertion `info->called == FALSE' failed
May  9 16:48:34 cthulhu NetworkManager: <info>  (ttyUSB0): cleaning up...
May  9 16:48:34 cthulhu NetworkManager: <info>  (ttyUSB0): taking down device.
May  9 16:48:34 cthulhu kernel: usb 5-2: reset full speed USB device using uhci_hcd and address 6
May  9 16:48:35 cthulhu kernel: usb 5-2: reset full speed USB device using uhci_hcd and address 6
May  9 16:48:35 cthulhu kernel: usb 5-2: device descriptor read/64, error -71
May  9 16:48:35 cthulhu kernel: usb 5-2: USB disconnect, address 6
May  9 16:48:35 cthulhu kernel: scsi 15:0:0:0: rejecting I/O to dead device
May  9 16:48:35 cthulhu kernel: scsi 15:0:0:0: rejecting I/O to dead device


Below the logs after killing devkit-disks-daemon, the connection succeeded:


May  9 16:49:53 cthulhu kernel: usb 5-2: new full speed USB device using uhci_hcd and address 7
May  9 16:49:53 cthulhu kernel: usb 5-2: New USB device found, idVendor=12d1, idProduct=1003
May  9 16:49:53 cthulhu kernel: usb 5-2: New USB device strings: Mfr=1, Product=2, SerialNumber=0
May  9 16:49:53 cthulhu kernel: usb 5-2: Product: HUAWEI Mobile
May  9 16:49:53 cthulhu kernel: usb 5-2: Manufacturer: HUAWEI Technologies
May  9 16:49:53 cthulhu kernel: scsi16 : usb-storage 5-2:1.0
May  9 16:49:53 cthulhu kernel: usb 5-2: USB disconnect, address 7
May  9 16:49:54 cthulhu kernel: usb 5-2: new full speed USB device using uhci_hcd and address 8
May  9 16:49:54 cthulhu kernel: usb 5-2: New USB device found, idVendor=12d1, idProduct=1003
May  9 16:49:54 cthulhu kernel: usb 5-2: New USB device strings: Mfr=1, Product=2, SerialNumber=0
May  9 16:49:54 cthulhu kernel: usb 5-2: Product: HUAWEI Mobile
May  9 16:49:54 cthulhu kernel: usb 5-2: Manufacturer: HUAWEI Technologies
May  9 16:49:54 cthulhu kernel: option 5-2:1.0: GSM modem (1-port) converter detected
May  9 16:49:54 cthulhu kernel: usb 5-2: GSM modem (1-port) converter now attached to ttyUSB0
May  9 16:49:54 cthulhu kernel: option 5-2:1.1: GSM modem (1-port) converter detected
May  9 16:49:54 cthulhu kernel: usb 5-2: GSM modem (1-port) converter now attached to ttyUSB1
May  9 16:49:54 cthulhu kernel: scsi19 : usb-storage 5-2:1.2
May  9 16:49:54 cthulhu modem-manager: (Huawei): (ttyUSB1) deferring support check
May  9 16:49:54 cthulhu modem-manager: (ttyUSB0) opening serial device...
May  9 16:49:54 cthulhu modem-manager: (ttyUSB0): probe requested by plugin 'Huawei'
May  9 16:49:57 cthulhu modem-manager: (ttyUSB1): re-checking support...
May  9 16:49:57 cthulhu modem-manager: (Huawei): (ttyUSB1) deferring support check
May  9 16:49:59 cthulhu kernel: scsi 19:0:0:0: CD-ROM            HUAWEI   Mass Storage     2.31 PQ: 0 ANSI: 2
May  9 16:49:59 cthulhu kernel: sr2: scsi-1 drive
May  9 16:49:59 cthulhu kernel: sr 19:0:0:0: Attached scsi CD-ROM sr2
May  9 16:49:59 cthulhu kernel: sr 19:0:0:0: Attached scsi generic sg3 type 5
May  9 16:50:00 cthulhu modem-manager: (ttyUSB1): re-checking support...
May  9 16:50:00 cthulhu modem-manager: (Huawei): (ttyUSB1) deferring support check
May  9 16:50:03 cthulhu modem-manager: (ttyUSB1): re-checking support...
May  9 16:50:03 cthulhu modem-manager: (Huawei): (ttyUSB1) deferring support check
May  9 16:50:06 cthulhu modem-manager: (ttyUSB1): re-checking support...
May  9 16:50:06 cthulhu modem-manager: (Huawei): (ttyUSB1) deferring support check
May  9 16:50:07 cthulhu modem-manager: (ttyUSB0) closing serial device...
May  9 16:50:07 cthulhu modem-manager: (Huawei): GSM modem /sys/devices/pci0000:00/0000:00:1d.0/usb5/5-2 claimed port ttyUSB0
May  9 16:50:07 cthulhu modem-manager: Added modem /sys/devices/pci0000:00/0000:00:1d.0/usb5/5-2
May  9 16:50:07 cthulhu modem-manager: Exported modem /sys/devices/pci0000:00/0000:00:1d.0/usb5/5-2 as /org/freedesktop/ModemManager/Modems/2
May  9 16:50:07 cthulhu NetworkManager: <info>  (ttyUSB0): new GSM device (driver: 'option1')
May  9 16:50:07 cthulhu NetworkManager: <info>  (ttyUSB0): exported as /org/freedesktop/NetworkManager/Devices/4
May  9 16:50:07 cthulhu NetworkManager: <info>  (ttyUSB0): now managed
May  9 16:50:07 cthulhu NetworkManager: <info>  (ttyUSB0): device state change: 1 -> 2 (reason 2)
May  9 16:50:07 cthulhu NetworkManager: <info>  (ttyUSB0): deactivating device (reason: 2).
May  9 16:50:07 cthulhu NetworkManager: <info>  (ttyUSB0): device state change: 2 -> 3 (reason 0)
May  9 16:50:07 cthulhu NetworkManager: <info>  Activation (ttyUSB0) starting connection 'Connexion GSM SFR'
May  9 16:50:07 cthulhu NetworkManager: <info>  (ttyUSB0): device state change: 3 -> 4 (reason 0)
May  9 16:50:07 cthulhu NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) scheduled...
May  9 16:50:07 cthulhu NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) started...
May  9 16:50:07 cthulhu NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) complete.
May  9 16:50:07 cthulhu modem-manager: (ttyUSB0) opening serial device...
May  9 16:50:07 cthulhu modem-manager: Modem /org/freedesktop/ModemManager/Modems/2: state changed (disabled -> enabling)
May  9 16:50:07 cthulhu modem-manager: Got failure code 11: SIM PIN required
May  9 16:50:07 cthulhu modem-manager: Modem /org/freedesktop/ModemManager/Modems/2: state changed (enabling -> enabled)
May  9 16:50:07 cthulhu modem-manager: Registration state changed: 2
May  9 16:50:07 cthulhu modem-manager: Modem /org/freedesktop/ModemManager/Modems/2: state changed (enabled -> searching)
May  9 16:50:09 cthulhu modem-manager: (ttyUSB1): re-checking support...
May  9 16:50:09 cthulhu modem-manager: (ttyUSB1) opening serial device...
May  9 16:50:09 cthulhu modem-manager: (ttyUSB1) closing serial device...
May  9 16:50:09 cthulhu modem-manager: (Huawei): GSM modem /sys/devices/pci0000:00/0000:00:1d.0/usb5/5-2 claimed port ttyUSB1
May  9 16:50:11 cthulhu modem-manager: Registration state changed: 1
May  9 16:50:11 cthulhu modem-manager: Modem /org/freedesktop/ModemManager/Modems/2: state changed (searching -> registered)
May  9 16:50:11 cthulhu modem-manager: Modem /org/freedesktop/ModemManager/Modems/2: state changed (registered -> connecting)
May  9 16:50:11 cthulhu modem-manager: Modem /org/freedesktop/ModemManager/Modems/2: state changed (connecting -> connected)
May  9 16:50:11 cthulhu NetworkManager: <info>  Activation (ttyUSB0) Stage 2 of 5 (Device Configure) scheduled...
May  9 16:50:11 cthulhu NetworkManager: <info>  Activation (ttyUSB0) Stage 2 of 5 (Device Configure) starting...
May  9 16:50:11 cthulhu NetworkManager: <info>  (ttyUSB0): device state change: 4 -> 5 (reason 0)
May  9 16:50:11 cthulhu NetworkManager: <info>  Activation (ttyUSB0) Stage 2 of 5 (Device Configure) successful.
May  9 16:50:11 cthulhu NetworkManager: <info>  Activation (ttyUSB0) Stage 3 of 5 (IP Configure Start) scheduled.
May  9 16:50:11 cthulhu NetworkManager: <info>  Activation (ttyUSB0) Stage 2 of 5 (Device Configure) complete.
May  9 16:50:11 cthulhu NetworkManager: <info>  Activation (ttyUSB0) Stage 3 of 5 (IP Configure Start) started...
May  9 16:50:11 cthulhu NetworkManager: <info>  (ttyUSB0): device state change: 5 -> 7 (reason 0)
May  9 16:50:11 cthulhu NetworkManager: <info>  Starting pppd connection
May  9 16:50:11 cthulhu NetworkManager: <debug> [1273416611.180686] nm_ppp_manager_start(): Command line: /usr/sbin/pppd nodetach lock nodefaultroute user slsfr ttyUSB0 noipdefault noauth refuse-eap refuse-mschap refuse-mschap-v2 usepeerdns lcp-echo-failure 0 lcp-echo-interval 0 ipparam /org/freedesktop/NetworkManager/PPP/2 plugin /usr/lib/pppd/2.4.4/nm-pppd-plugin.so
May  9 16:50:11 cthulhu NetworkManager: <debug> [1273416611.188326] nm_ppp_manager_start(): ppp started with pid 16339
May  9 16:50:11 cthulhu NetworkManager: <info>  Activation (ttyUSB0) Stage 4 of 5 (IP6 Configure Get) scheduled...
May  9 16:50:11 cthulhu NetworkManager: <info>  Activation (ttyUSB0) Stage 3 of 5 (IP Configure Start) complete.
May  9 16:50:11 cthulhu NetworkManager: <info>  Activation (ttyUSB0) Stage 4 of 5 (IP6 Configure Get) started...
May  9 16:50:11 cthulhu NetworkManager: <info>  Activation (ttyUSB0) Stage 4 of 5 (IP6 Configure Get) complete.
May  9 16:50:11 cthulhu pppd[16339]: Plugin /usr/lib/pppd/2.4.4/nm-pppd-plugin.so loaded.
May  9 16:50:11 cthulhu pppd[16339]: pppd 2.4.4 started by root, uid 0
May  9 16:50:11 cthulhu pppd[16339]: Using interface ppp0
May  9 16:50:11 cthulhu pppd[16339]: Connect: ppp0 <--> /dev/ttyUSB0
May  9 16:50:11 cthulhu NetworkManager:    SCPlugin-Ifupdown: devices added (path: /sys/devices/virtual/net/ppp0, iface: ppp0)
May  9 16:50:11 cthulhu NetworkManager:    SCPlugin-Ifupdown: device added (path: /sys/devices/virtual/net/ppp0, iface: ppp0): no ifupdown configuration found.
May  9 16:50:11 cthulhu pppd[16339]: CHAP authentication succeeded
May  9 16:50:11 cthulhu pppd[16339]: CHAP authentication succeeded
May  9 16:50:31 cthulhu NetworkManager: <WARN>  pppd_timed_out(): Looks like pppd didn't initialize our dbus module
May  9 16:50:31 cthulhu NetworkManager: <info>  (ttyUSB0): device state change: 7 -> 9 (reason 14)
May  9 16:50:31 cthulhu NetworkManager: <info>  Marking connection 'Connexion GSM SFR' invalid.
May  9 16:50:31 cthulhu NetworkManager: <info>  Activation (ttyUSB0) failed.
May  9 16:50:31 cthulhu NetworkManager: <info>  (ttyUSB0): device state change: 9 -> 3 (reason 0)
May  9 16:50:31 cthulhu NetworkManager: <info>  (ttyUSB0): deactivating device (reason: 0).
May  9 16:50:31 cthulhu pppd[16339]: Terminating on signal 15
May  9 16:50:31 cthulhu modem-manager: Modem /org/freedesktop/ModemManager/Modems/2: state changed (connected -> disconnecting)
May  9 16:50:31 cthulhu pppd[16339]: Connection terminated.
May  9 16:50:31 cthulhu NetworkManager:    SCPlugin-Ifupdown: devices removed (path: /sys/devices/virtual/net/ppp0, iface: ppp0)
May  9 16:50:31 cthulhu modem-manager: Got failure code 3: No carrier
May  9 16:50:32 cthulhu modem-manager: Modem /org/freedesktop/ModemManager/Modems/2: state changed (disconnecting -> registered)
May  9 16:50:32 cthulhu pppd[16339]: Exit.
May  9 16:50:33 cthulhu NetworkManager: <debug> [1273416633.001757] ensure_killed(): waiting for ppp pid 16339 to exit
May  9 16:50:33 cthulhu NetworkManager: <debug> [1273416633.001871] ensure_killed(): ppp pid 16339 cleaned up
May  9 16:50:42 cthulhu NetworkManager: <info>  Activation (ttyUSB0) starting connection 'Connexion GSM SFR'
May  9 16:50:42 cthulhu NetworkManager: <info>  (ttyUSB0): device state change: 3 -> 4 (reason 0)
May  9 16:50:42 cthulhu NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) scheduled...
May  9 16:50:42 cthulhu NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) started...
May  9 16:50:42 cthulhu NetworkManager: <info>  (ttyUSB0): device state change: 4 -> 6 (reason 0)
May  9 16:50:42 cthulhu NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) complete.
May  9 16:50:42 cthulhu NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) scheduled...
May  9 16:50:42 cthulhu NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) started...
May  9 16:50:42 cthulhu NetworkManager: <info>  (ttyUSB0): device state change: 6 -> 4 (reason 0)
May  9 16:50:42 cthulhu NetworkManager: <info>  Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) complete.
May  9 16:50:42 cthulhu modem-manager: Modem /org/freedesktop/ModemManager/Modems/2: state changed (registered -> connecting)
May  9 16:50:42 cthulhu modem-manager: Modem /org/freedesktop/ModemManager/Modems/2: state changed (connecting -> connected)
May  9 16:50:42 cthulhu NetworkManager: <info>  Activation (ttyUSB0) Stage 2 of 5 (Device Configure) scheduled...
May  9 16:50:42 cthulhu NetworkManager: <info>  Activation (ttyUSB0) Stage 2 of 5 (Device Configure) starting...
May  9 16:50:42 cthulhu NetworkManager: <info>  (ttyUSB0): device state change: 4 -> 5 (reason 0)
May  9 16:50:42 cthulhu NetworkManager: <info>  Activation (ttyUSB0) Stage 2 of 5 (Device Configure) successful.
May  9 16:50:42 cthulhu NetworkManager: <info>  Activation (ttyUSB0) Stage 3 of 5 (IP Configure Start) scheduled.
May  9 16:50:42 cthulhu NetworkManager: <info>  Activation (ttyUSB0) Stage 2 of 5 (Device Configure) complete.
May  9 16:50:42 cthulhu NetworkManager: <info>  Activation (ttyUSB0) Stage 3 of 5 (IP Configure Start) started...
May  9 16:50:42 cthulhu NetworkManager: <info>  (ttyUSB0): device state change: 5 -> 7 (reason 0)
May  9 16:50:42 cthulhu NetworkManager: <info>  Starting pppd connection
May  9 16:50:42 cthulhu NetworkManager: <debug> [1273416642.833057] nm_ppp_manager_start(): Command line: /usr/sbin/pppd nodetach lock nodefaultroute user slsfr ttyUSB0 noipdefault noauth refuse-eap refuse-mschap refuse-mschap-v2 usepeerdns lcp-echo-failure 0 lcp-echo-interval 0 ipparam /org/freedesktop/NetworkManager/PPP/3 plugin /usr/lib/pppd/2.4.4/nm-pppd-plugin.so
May  9 16:50:42 cthulhu NetworkManager: <debug> [1273416642.835066] nm_ppp_manager_start(): ppp started with pid 16530
May  9 16:50:42 cthulhu NetworkManager: <info>  Activation (ttyUSB0) Stage 4 of 5 (IP6 Configure Get) scheduled...
May  9 16:50:42 cthulhu NetworkManager: <info>  Activation (ttyUSB0) Stage 3 of 5 (IP Configure Start) complete.
May  9 16:50:42 cthulhu NetworkManager: <info>  Activation (ttyUSB0) Stage 4 of 5 (IP6 Configure Get) started...
May  9 16:50:42 cthulhu NetworkManager: <info>  Activation (ttyUSB0) Stage 4 of 5 (IP6 Configure Get) complete.
May  9 16:50:42 cthulhu pppd[16530]: Plugin /usr/lib/pppd/2.4.4/nm-pppd-plugin.so loaded.
May  9 16:50:42 cthulhu pppd[16530]: pppd 2.4.4 started by root, uid 0
May  9 16:50:42 cthulhu pppd[16530]: Using interface ppp0
May  9 16:50:42 cthulhu pppd[16530]: Connect: ppp0 <--> /dev/ttyUSB0
May  9 16:50:42 cthulhu pppd[16530]: CHAP authentication succeeded
May  9 16:50:42 cthulhu pppd[16530]: CHAP authentication succeeded
May  9 16:50:42 cthulhu NetworkManager:    SCPlugin-Ifupdown: devices added (path: /sys/devices/virtual/net/ppp0, iface: ppp0)
May  9 16:50:42 cthulhu NetworkManager:    SCPlugin-Ifupdown: device added (path: /sys/devices/virtual/net/ppp0, iface: ppp0): no ifupdown configuration found.
May  9 16:50:51 cthulhu pppd[16530]: Could not determine remote IP address: defaulting to 10.64.64.64
May  9 16:50:51 cthulhu pppd[16530]: Cannot determine ethernet address for proxy ARP
May  9 16:50:51 cthulhu pppd[16530]: local  IP address 10.50.219.213
May  9 16:50:51 cthulhu pppd[16530]: remote IP address 10.64.64.64
May  9 16:50:51 cthulhu pppd[16530]: primary   DNS address 172.20.2.39
May  9 16:50:51 cthulhu pppd[16530]: secondary DNS address 172.20.2.10
May  9 16:50:51 cthulhu NetworkManager: <info>  PPP manager(IP Config Get) reply received.
May  9 16:50:51 cthulhu NetworkManager: <info>  Activation (ttyUSB0) Stage 4 of 5 (IP4 Configure Get) scheduled...
May  9 16:50:51 cthulhu NetworkManager: <info>  Activation (ttyUSB0) Stage 4 of 5 (IP4 Configure Get) started...
May  9 16:50:51 cthulhu NetworkManager: <info>  Activation (ttyUSB0) Stage 5 of 5 (IP Configure Commit) scheduled...
May  9 16:50:51 cthulhu NetworkManager: <info>  Activation (ttyUSB0) Stage 4 of 5 (IP4 Configure Get) complete.
May  9 16:50:51 cthulhu NetworkManager: <info>  Activation (ttyUSB0) Stage 5 of 5 (IP Configure Commit) started...
May  9 16:50:51 cthulhu postfix/master[2268]: reload -- version 2.6.5, configuration /etc/postfix
May  9 16:50:52 cthulhu NetworkManager: <info>  (ttyUSB0): device state change: 7 -> 8 (reason 0)
May  9 16:50:52 cthulhu NetworkManager: <info>  Policy set 'Connexion GSM SFR' (ppp0) as default for routing and DNS.
May  9 16:50:52 cthulhu NetworkManager: <info>  Activation (ttyUSB0) successful, device activated.
May  9 16:50:52 cthulhu NetworkManager: <info>  Activation (ttyUSB0) Stage 5 of 5 (IP Configure Commit) complete.


I can test usbmon if you guide me.

I will test the changes on the file /etc/udev/rules.d/70-persistent-cd.rules (https://bugs.launchpad.net/ubuntu/+source/linux/+bug/449394/comments/68).


Regards.
Comment 29 Alan Stern 2010-05-09 17:40:59 UTC
On Sun, 9 May 2010 bugzilla-daemon@bugzilla.kernel.org wrote:

> I tested the method of Damjan Jovanovic by killing devkit-disks-daemon
> (Debian
> package devicekit-disks 009-3).
> 
> Below the logs before killing devkit-disks-daemon, the connection fails:
> 
> May  9 16:48:18 cthulhu kernel: usb 5-2: new full speed USB device using
> uhci_hcd and address 5
> May  9 16:48:19 cthulhu kernel: usb 5-2: New USB device found, idVendor=12d1,
> idProduct=1003
> May  9 16:48:19 cthulhu kernel: usb 5-2: New USB device strings: Mfr=1,
> Product=2, SerialNumber=0
> May  9 16:48:19 cthulhu kernel: usb 5-2: Product: HUAWEI Mobile
...

> Below the logs after killing devkit-disks-daemon, the connection succeeded:
...

> I can test usbmon if you guide me.

Please do.  Using usbmon is easy:

	mount -t debugfs none /sys/kernel/debug
	cat /sys/kernel/debug/usb/usbmon/5u >usbmon.log

Here the "5u" refers to the "usb 5-2" in the log above; if the bus number
changes from 5 to something else then you would use the new value instead.

While this is running, plug in the modem.  After the failure occurs, 
kill the "cat" program with ^C.  The usbmon.log file will contain the 
recorded information.  Attach it to the bug report.

Make sure that devkit-disks-daemon is running when you do the test, so
we can see what command it sends that the modem doesn't like.  Also, it
will help if you unplug as many of your other USB devices as possible
before starting the test.

Alan Stern
Comment 30 Frederic MASSOT 2010-05-14 01:45:09 UTC
Hi,

I tested the changes on the file "/etc/udev/rules.d/70-persistent-cd.rules"
(https://bugs.launchpad.net/ubuntu/+source/linux/+bug/449394/comments/68), but it does not work.

But my version of Gnome is not yet using udisks, I use devicekit-disks add the name (UDISKS_DISABLE_POLLING, UDISKS_PRESENTATION_NOPOLICY) to be different.


Regards.
Comment 31 Frederic MASSOT 2010-05-14 01:48:39 UTC
Hi,

I used usbmon to record information. I attached the log file.


Regards.
Comment 32 Frederic MASSOT 2010-05-14 01:49:40 UTC
Created attachment 26372 [details]
usbmon log file
Comment 33 Frederic MASSOT 2010-05-14 01:57:50 UTC
Hi,

With Gnome, after killing devicekit-disks, I connect to the Internet. I run the commands :

# devkit-disks --enumerate
/org/freedesktop/DeviceKit/Disks/devices/sr1
/org/freedesktop/DeviceKit/Disks/devices/sda1
/org/freedesktop/DeviceKit/Disks/devices/sda2
/org/freedesktop/DeviceKit/Disks/devices/sda
/org/freedesktop/DeviceKit/Disks/devices/sr2
/org/freedesktop/DeviceKit/Disks/devices/sr0
/org/freedesktop/DeviceKit/Disks/devices/fd0

It will not reset the E220, the connection remains active. sr2 is associated to the E220.

In the logs I have this:

May 14 03:52:21 cthulhu kernel: sr2: CDROM (ioctl) error, command: cdb[0]=0x51 51 00 00 00 00 00 00 00 02 00
May 14 03:52:21 cthulhu kernel: sr: Sense Key : 0x4 [current] 
May 14 03:52:21 cthulhu kernel: sr: ASC=0x0 ASCQ=0x0
May 14 03:52:23 cthulhu kernel: sr2: CDROM (ioctl) error, command: cdb[0]=0x46 46 00 00 00 00 00 00 00 20 00
May 14 03:52:23 cthulhu kernel: sr: Sense Key : 0x4 [current] 
May 14 03:52:23 cthulhu kernel: sr: ASC=0x0 ASCQ=0x0
May 14 03:52:23 cthulhu kernel: sr2: CDROM (ioctl) error, command: cdb[0]=0x46 46 00 00 00 00 00 00 00 20 00
May 14 03:52:23 cthulhu kernel: sr: Sense Key : 0x4 [current] 
May 14 03:52:23 cthulhu kernel: sr: ASC=0x0 ASCQ=0x0
May 14 03:52:23 cthulhu kernel: sr2: CDROM (ioctl) error, command: cdb[0]=0x46 46 00 00 00 00 00 00 00 20 00
May 14 03:52:23 cthulhu kernel: sr: Sense Key : 0x4 [current] 
May 14 03:52:23 cthulhu kernel: sr: ASC=0x0 ASCQ=0x0



Regards.
Comment 34 Alan Stern 2010-05-24 18:56:50 UTC
On Fri, 14 May 2010 bugzilla-daemon@bugzilla.kernel.org wrote:

> In the logs I have this:
> 
> May 14 03:52:21 cthulhu kernel: sr2: CDROM (ioctl) error, command:
> cdb[0]=0x51
> 51 00 00 00 00 00 00 00 02 00
> May 14 03:52:21 cthulhu kernel: sr: Sense Key : 0x4 [current] 
> May 14 03:52:21 cthulhu kernel: sr: ASC=0x0 ASCQ=0x0
> May 14 03:52:23 cthulhu kernel: sr2: CDROM (ioctl) error, command:
> cdb[0]=0x46
> 46 00 00 00 00 00 00 00 20 00
> May 14 03:52:23 cthulhu kernel: sr: Sense Key : 0x4 [current] 
> May 14 03:52:23 cthulhu kernel: sr: ASC=0x0 ASCQ=0x0
> May 14 03:52:23 cthulhu kernel: sr2: CDROM (ioctl) error, command:
> cdb[0]=0x46
> 46 00 00 00 00 00 00 00 20 00
> May 14 03:52:23 cthulhu kernel: sr: Sense Key : 0x4 [current] 
> May 14 03:52:23 cthulhu kernel: sr: ASC=0x0 ASCQ=0x0
> May 14 03:52:23 cthulhu kernel: sr2: CDROM (ioctl) error, command:
> cdb[0]=0x46
> 46 00 00 00 00 00 00 00 20 00
> May 14 03:52:23 cthulhu kernel: sr: Sense Key : 0x4 [current] 
> May 14 03:52:23 cthulhu kernel: sr: ASC=0x0 ASCQ=0x0

I think those errors are harmless, although they do indicate a bug in 
the firmware.  More important is an error that occurs later:

f5518300 240909067 S Bo:5:004:4 -115 31 = 55534243 d5000000 0a000000 80000a5a 082a0000 0000000a 00000000 000000
f5518300 240909911 C Bo:5:004:4 0 31 >
f50c1800 240909979 S Bi:5:004:3 -115 10 <
f50c1800 240939906 C Bi:5:004:3 -75 10 = 0e000000 00000800 0000
f5518300 240939984 S Bi:5:004:3 -115 13 <
f5518300 240940908 C Bi:5:004:3 -75 13 = 0e000000 00000800 0000ffff 00

This is also due to a firmware bug, and it _does_ cause the device to 
be reset.

Have you checked the version of the firmware in your E220?  Is there an 
update available for you to install?

Alan Stern
Comment 35 Damjan Jovanovic 2010-05-24 19:13:44 UTC
The NetworkManager mobile broadband page (http://live.gnome.org/NetworkManager/MobileBroadband) documents that the minimum working firmware version for the Huawei E220 is 11.117.09.04.00

You can check the firmware version by typing this in one terminal:
sudo cat /dev/ttyUSB0

and this in another:
echo "ATI" > /dev/ttyUSB0

Without the new firmware, I've heard the E220 doesn't work on newer versions of Windows either.

Unfortunately the firmware upgrade must be done on Windows.
Comment 36 Frederic MASSOT 2010-05-26 14:05:06 UTC
Hi,

I updated the firmware of the Huawei E220 with version 11.117.09.04.00, and the problems have been resolved.

I can use Gnome and I connect to the Internet, I can browse the contents of the Huawei E220, and I am no longer obliged to throw twice Network-Manager to activate the network. Fucking bug !!!  :o)

I downloaded the firmware here : 
http://www.vodafone.de/hilfe-support/technischer-support/129464.html

Regards.
Comment 37 Alan Stern 2010-05-26 14:44:57 UTC
On Wed, 26 May 2010 bugzilla-daemon@bugzilla.kernel.org wrote:

> --- Comment #36 from Frederic MASSOT <frederic@juliana-multimedia.com> 
> 2010-05-26 14:05:06 ---
> Hi,
> 
> I updated the firmware of the Huawei E220 with version 11.117.09.04.00, and
> the
> problems have been resolved.

Damjan (or anyone else): Under these circumstances, is there any reason 
to keep this bug report open?

Alan Stern
Comment 38 Alan Stern 2010-10-07 15:58:32 UTC
In the absence of any response, I'm closing out this bug report.
Comment 39 Martin Mokrejs 2011-07-10 14:25:03 UTC
Hi Alan,
  it still does happen even with newer devices and kernels. I have same problem with 2.6.38.8 and 2.6.39.2 with Huawei E1823:

Manufacturer: huawei
Model: E1823
Revision: 11.825.03.10.55
IMEI: xxxx
+GCAP: +CGSM,+FCLASS,+DS



As others am getting the:

option: option_instat_callback: error -84
or
option: option_instat_callback: error -108

I made the usbmon log (Huawei1823-2.6.39.2.usbmon.log) and attach the dmesg (Huawei1823-2.6.39.2.txt). It was weird to me yesterday it worked for me while today not. And I tried external USB hub via USB1 port, via PCMCIA to USB2.0 to the hub, also plugged the USB stick directly into my old laptop. And I think at least for today I can conclude what was the cause - I forgot to run on power from the wall socket. ;) I got fooled because the LED lights on the USB hub were on, and the only hint was probably the fact that once pppd managed to dial in, negotiate but then it broke quickly (will attach Huawei1823-2.6.39.2.txt2).


I am not saying it could NOT happen for other reasons but at least I have incidentally some explanation.


For completeness, my working setup (at least time to time): ;)

# pppd ttyUSB0 460800 connect '/usr/sbin/chat -v -f /etc/ppp/chat-tmobile' dump debug
pppd options in effect:
debug debug             # (from /etc/ppp/options.ttyUSB0)
nodetach                # (from /etc/ppp/options.ttyUSB0)
persist         # (from /etc/ppp/options.ttyUSB0)
maxfail 0               # (from /etc/ppp/options.ttyUSB0)
unit 9          # (from /etc/ppp/options.ttyUSB0)
dump            # (from command line)
noauth          # (from /etc/ppp/options.ttyUSB0)
user gprs               # (from /etc/ppp/options.ttyUSB0)
password ??????         # (from /etc/ppp/options.ttyUSB0)
/dev/ttyUSB0            # (from command line)
460800          # (from command line)
lock            # (from /etc/ppp/options.ttyUSB0)
connect /usr/sbin/chat -v -f /etc/ppp/chat-tmobile              # (from command line)
crtscts         # (from /etc/ppp/options.ttyUSB0)
mtu 1492                # (from /etc/ppp/options.ttyUSB0)
ipcp-accept-local               # (from /etc/ppp/options.ttyUSB0)
ipcp-accept-remote              # (from /etc/ppp/options.ttyUSB0)
noipdefault             # (from /etc/ppp/options.ttyUSB0)
defaultroute            # (from /etc/ppp/options.ttyUSB0)
usepeerdns              # (from /etc/ppp/options.ttyUSB0)

Waiting for CONNECT string
chat:  Jul 10 16:08:51 CONNECT 236800
Script /usr/sbin/chat -v -f /etc/ppp/chat-tmobile finished (pid 9630), status = 0x0
Serial connection established.
using channel 4
Using interface ppp9
Connect: ppp9 <--> /dev/ttyUSB0
sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x44bb728d> <pcomp> <accomp>]
rcvd [LCP ConfReq id=0x0 <asyncmap 0x0> <auth chap MD5> <magic 0x2d88ca6> <pcomp> <accomp>]
sent [LCP ConfAck id=0x0 <asyncmap 0x0> <auth chap MD5> <magic 0x2d88ca6> <pcomp> <accomp>]
rcvd [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0x44bb728d> <pcomp> <accomp>]
rcvd [LCP DiscReq id=0x1 magic=0x2d88ca6]
rcvd [CHAP Challenge id=0x1 <a4c7fb0100e1ef3834e49c0c64184a10>, name = "UMTS_CHAP_SRVR"]
sent [CHAP Response id=0x1 <991c62c942c5e614fe543c4d2cb2093b>, name = "gprs"]
rcvd [CHAP Success id=0x1 ""]
CHAP authentication succeeded
CHAP authentication succeeded
sent [CCP ConfReq id=0x1 <deflate 15> <deflate(old#) 15> <bsd v1 15>]
sent [IPCP ConfReq id=0x1 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
rcvd [LCP ProtRej id=0x2 80 fd 01 01 00 0f 1a 04 78 00 18 04 78 00 15 03 2f]
Protocol-Reject for 'Compression Control Protocol' (0x80fd) received
rcvd [IPCP ConfNak id=0x1 <ms-dns1 10.11.12.13> <ms-dns2 10.11.12.14> <ms-wins 10.11.12.13> <ms-wins 10.11.12.14>]
sent [IPCP ConfReq id=0x2 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 10.11.12.13> <ms-dns2 10.11.12.14>]
rcvd [IPCP ConfNak id=0x2 <ms-dns1 10.11.12.13> <ms-dns2 10.11.12.14> <ms-wins 10.11.12.13> <ms-wins 10.11.12.14>]
sent [IPCP ConfReq id=0x3 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 10.11.12.13> <ms-dns2 10.11.12.14>]
rcvd [IPCP ConfNak id=0x3 <ms-dns1 10.11.12.13> <ms-dns2 10.11.12.14> <ms-wins 10.11.12.13> <ms-wins 10.11.12.14>]
sent [IPCP ConfReq id=0x4 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 10.11.12.13> <ms-dns2 10.11.12.14>]
rcvd [IPCP ConfReq id=0x0]
sent [IPCP ConfNak id=0x0 <addr 0.0.0.0>]
rcvd [IPCP ConfRej id=0x4 <compress VJ 0f 01>]
sent [IPCP ConfReq id=0x5 <addr 0.0.0.0> <ms-dns1 10.11.12.13> <ms-dns2 10.11.12.14>]
rcvd [IPCP ConfReq id=0x1]
sent [IPCP ConfAck id=0x1]
rcvd [IPCP ConfNak id=0x5 <addr 93.153.87.160> <ms-dns1 93.153.117.1> <ms-dns2 62.141.0.2>]
sent [IPCP ConfReq id=0x6 <addr 93.153.87.160> <ms-dns1 93.153.117.1> <ms-dns2 62.141.0.2>]
rcvd [IPCP ConfAck id=0x6 <addr 93.153.87.160> <ms-dns1 93.153.117.1> <ms-dns2 62.141.0.2>]
Could not determine remote IP address: defaulting to 10.64.64.73
local  IP address 93.153.87.160
remote IP address 10.64.64.73
primary   DNS address 93.153.117.1
secondary DNS address 62.141.0.2
Script /etc/ppp/ip-up started (pid 9632)
Script /etc/ppp/ip-up finished (pid 9632), status = 0x0
Comment 40 Martin Mokrejs 2011-07-10 14:27:26 UTC
Created attachment 65152 [details]
dmesg from 2.6.39.2 with Huawei E1823

battery-powered laptop, USB hub powered from the laptop
Comment 41 Martin Mokrejs 2011-07-10 14:28:23 UTC
Created attachment 65162 [details]
Huawei1823-2.6.39.2.usbmon.log

when on the battery power and failing
Comment 42 Martin Mokrejs 2011-07-10 14:30:01 UTC
Created attachment 65172 [details]
once it got briefly enough power - Huawei E1823 on 2.6.39.2

Note You need to log in before you can comment on or make changes to this bug.