K3520-Z mode not switched automatically

[Dane Maslen]

Ubuntu 12.04.2 LTS

Although I have logged this as a network-manager problem, it could well turn out to be an issue with usb-modeswitch (usb-modeswitch 1.2.3+repack0-1ubuntu2) or usb-modeswitch-data (usb-modeswitch-data 20120120-0ubuntu1).

Expected behaviour (and what happened in 10.04):
 * The presence of mobile broadband dongle K3520-Z should be detected.
 * The appropriate steps should be taken to switch it from usb-storage mode.
 * Mobile broadband should be enabled.

What actually happens:
 * The dongle remains in usb-storage mode.
 * Mobile broadband does not appear as an option on the network drop-down menu.

The following commands can be used to work around the problem:

sudo modprobe --verbose option

sudo echo "19d2 0055" >/sys/bus/usb-serial/drivers/option1/new_id

sudo usb_modeswitch --default-vendor 0x19d2 --default-product 0x2000 --message-content "5553424312345678000000000000061e000000000000000000000000000000" --message-content2="5553424312345679000000000000061b000000020000000000000000000000" --message-content3="55534243123456702000000080000c85010101180101010101000000000000" --need-response --target-vendor 0x19d2 --target-product 0x0055 -s 20 -D

After these commands mobile broadband appears as a disabled option in the network drop-down menu. Once mobile broadband is manually enabled, all is well.

The remainder of this bug report might or might not contain useful information.

When I tried researching this problem, I encountered threads in various forums that seemed to be reporting the same failure but for different dongles. This bug might therefore not be limited to the K3520-Z, but I do know that it doesn't apply to a K3770 as I also have one of those (I suppose I could swap the SIM from the K3520-Z to the K3770 to work around the problem, but I'd rather not risk damaging the SIM in the process).

When I first encountered this problem after upgrading from 10.04.01 to 12.04.2, I was puzzled by the fact that mobile broadband had worked perfectly after the upgrade completed but then failed on a later startup. I was further confused when from time to time it worked on subsequent startups. I have, however, now realised what was going on and have tested my understanding appropriately. Following a shutdown and startup mobile broadband fails because the dongle has been powered down and hence has reverted to usb-storage mode, but following a restart mobile broadband works (providing it was working prior to the restart) because the dongle has remained powered throughout and hence has not reverted to usb-storage mode.

This problem manifests itself in the same way on a netbook (I'll provide more details of the hardware if they are considered useful). This is what might well be expected, but I mention it because on 10.04.1 I had an entirely different experience. The K3520-Z used to switch mode automatically on both systems, but I had to switch the K3770 manually on the netbook (this is why I was able to come up with the above workaround after upgrading to 12.04.02 - I had done all the hard work discovering the workaround 18 months ago when I bought the K3770 while on holiday in Spain and now just needed to find the correct usb_modeswitch options for the K3520-Z). No, you haven't misread that. The dongle that switched mode automatically on both systems in 10.04.01 now fails to switch automatically on both in 12.04.02, while the one that switched automatically on only one of the two systems in 10.04.01 now switches automatically on both in 12.04.02.

If it's on any interest, the following is the output from the above commands:

Looking for target devices ...
 No devices in target mode or class found
Looking for default devices ...
   found matching product ID
   adding device
 Found device in default mode, class or configuration (1)
Accessing device 002 on bus 007 ...
Getting the current device configuration ...
 OK, got current device configuration (1)
Using first interface: 0x00
Using endpoints 0x09 (out) and 0x89 (in)
Inquiring device details; driver will be detached ...
Looking for active driver ...
 OK, driver found ("usb-storage")
 OK, driver "usb-storage" detached

SCSI inquiry data (for identification)
-------------------------
  Vendor String: ZTE Corp
   Model String: USB Storage
Revision String: 2.31
-------------------------

USB description data (for identification)
-------------------------
Manufacturer: Qualcomm, Incorporated
     Product: USB ZTE Storage
  Serial No.: P671M8VDF_MS
-------------------------
Setting up communication with interface 0
Using endpoint 0x09 for message sending ...
Trying to send message 1 to endpoint 0x09 ...
 OK, message successfully sent
Reading the response to message 1 (CSW) ...
 OK, response successfully read (13 bytes).
Trying to send message 2 to endpoint 0x09 ...
 OK, message successfully sent
Reading the response to message 2 (CSW) ...
 OK, response successfully read (0 bytes).
Trying to send message 3 to endpoint 0x09 ...
 OK, message successfully sent
Reading the response to message 3 (CSW) ...
 OK, response successfully read (0 bytes).
Resetting response endpoint 0x89
 Could not reset endpoint (probably harmless): -71
Resetting message endpoint 0x09
 Could not reset endpoint (probably harmless): -71
 Device is gone, skipping any further commands

Checking for mode switch (max. 20 times, once per second) ...
 Searching for target devices ...
 Searching for target devices ...
 Searching for target devices ...
   found matching product ID
   adding device

Found target device, now opening
Error: could not get description string "serial number"
 Found correct target device

Mode switch succeeded. Bye.

ok:19d2:0055

ProblemType: Bug
DistroRelease: Ubuntu 12.04
Package: network-manager 0.9.4.0-0ubuntu4.2
ProcVersionSignature: Ubuntu 3.2.0-40.64-generic 3.2.40
Uname: Linux 3.2.0-40-generic i686
ApportVersion: 2.0.1-0ubuntu17.2
Architecture: i386
CRDA: Error: command ['iw', 'reg', 'get'] failed with exit code 1: nl80211 not found.
Date: Wed May 1 08:51:46 2013
IfupdownConfig:
 auto lo
 iface lo inet loopback
IpRoute:
 default via 10.64.64.64 dev ppp0 proto static
 10.64.64.64 dev ppp0 proto kernel scope link src 10.162.121.221
 169.254.0.0/16 dev ppp0 scope link metric 1000
IwConfig:
 ppp0 no wireless extensions.

 lo no wireless extensions.

 eth0 no wireless extensions.
MarkForUpload: True
NetworkManager.state:
 [main]
 NetworkingEnabled=true
 WirelessEnabled=true
 WWANEnabled=true
ProcEnviron:
 TERM=xterm
 LC_COLLATE=C
 PATH=(custom, no user)
 LANG=en_GB.UTF-8
 SHELL=/bin/bash
RfKill:

SourcePackage: network-manager
UpgradeStatus: Upgraded to precise on 2013-04-30 (1 days ago)
nmcli-con:
 NAME UUID TYPE TIMESTAMP TIMESTAMP-REAL AUTOCONNECT READONLY DBUS-PATH
 Wired connection 1 f026e4a8-c33d-4dba-b3d6-7583ad941a94 802-3-ethernet 1367391728 Wed 01 May 2013 08:02:08 BST yes no /org/freedesktop/NetworkManager/Settings/1
 Vodafone UK 88242320-34e0-11e0-a76e-f9f1249a58d9 gsm 1367394427 Wed 01 May 2013 08:47:07 BST no no /org/freedesktop/NetworkManager/Settings/0
nmcli-dev:
 DEVICE TYPE STATE DBUS-PATH
 ttyUSB0 gsm connected /org/freedesktop/NetworkManager/Devices/2
 eth0 802-3-ethernet unavailable /org/freedesktop/NetworkManager/Devices/0
nmcli-nm:
 RUNNING VERSION STATE NET-ENABLED WIFI-HARDWARE WIFI WWAN-HARDWARE WWAN
 running 0.9.4.0 connected enabled enabled enabled enabled enabled

[Dane Maslen (dane-maslen)]

Having done some further investigation, I believe this is a udev issue, not a network manager issue.

Having issued the command
  udevadm control --log-priority=debug
I then inserted first the K3770 and then the K3520-Z. I've subsequently been looking at the very copious debug output from udev in syslog. For both dongles udev is successfully finding a rule and invoking usb_modeswitch but although the mode switch is successful for the K3770, it is unsuccessful for the K3520-Z. The way in which isb_modeswitch is being invoked by udev differs substantially for the two dongles. This surprises me given that the manual method for switching them is fairly similar.

I shall spend some more time trying to make greater sense of the udev debug output to see if I can identify the cause of the difference in the invocation of usb_modeswitch. Meanwhile if anyone would like me to upload the extracts from syslog for the K-3770 and the K3520-Z, let me know.

[Dane Maslen (dane-maslen)]

I've now done a lot more investigating and I'm pretty sure this is a problem in usb_modeswitch. If I knew how to modify this bug report to point the finger at usb_modeswitch rather than network-manager I would do so, but I can't see an obvious way to do so. Perhaps someone more familiar with Launchpad could do so for me. Thanks.

From my investigations I believe that this is what is supposed to happen when the mobile broadband dongle is pugged in:
 A: udev finds a matching rule in /lib/udev/rules.d/40-usb_modeswitch.rules (the rule matches based on key-value pairs for idVendor and idProduct and specifies the assignment pair RUN+="usb_modeswitch '%b/%k'")
 B: that causes udev to run the shell script lib/udev/usb_modeswitch
 C: the shell script execs the executable /usr/sbin/usb_modeswitch_dispatcher
 D: the executable consults information somewhere (in older versions of usb_modeswitch it was a collection of files in /etc/usb_modeswitch.d, but now I believe it is a single tar file somewhere) to determine the usb_modeswitch options required to switch the dongle out of usb storage mode
 E: the executable invokes /usr/sbin/usb_modeswitch with the appropriate options
 F: /usr/sbin/usb_modeswitch switches the dongle out of usb storage mode
 G: udev finds matching rules in /lib/udev/rules.d/40-usb_modeswitch.rules for the new device (i.e. the dongle switched out of usb storage mode); these rules specify the assignment pairs PROGRAM="usb_modeswitch --symlink-name %p %s{idVendor} %s{idProduct} %E{PRODUCT}", SYMLINK="%c" and RUN+="usb_modeswitch --driver-bind %p %s{idVendor} %s{idProduct} %E{PRODUCT}"
 H: that causes udev to run the shell script /lib/udev/usb_modeswitch
 I: the shell script loads the option driver (using modprobe) if it not already loaded and adds the dongle to the devices managed by the option driver (by writing the vendor id and product id to /sys/bus/usb-serial/drivers/option1/new_id)

In practice that's not what is happening. Either D or E is not happening correctly with the result that steps F to I are not occurring.

My original workaround did the equivalent of I and E manually. In the course of my further investigations I discovered that only E needed to be done. Once the dongle is switched manually out of usb storage mode, steps G to I automatically occur successfully.

I have now come up with a new workaround based on a udev rules file that effectively bypasses steps B, C and D (i.e. it bypasses usb_modeswitch_dispatcher which I strongly suspect to be the culprit here). With this workaround in place my K3520-Z now switches mode automatically when plugged in.

Anyone who has been paying close attention might well be wondering "But if all that is the case, how come the K3770 works?" The answer seems to be that something other than usb_modeswitch is switching it out of usb storage mode, but I have yet to deduce what is doing it. It is, however, certainly the case that even though steps A to F are not occurring for the K3770 it is switching modes such that steps G to I are then occurring.

Over the course of the next day or so I shall post further comments that provide the supporting evidence for various of the above as...

[Dane Maslen (dane-maslen)]

The attached file is an extract from syslog that includes debug output from udev when the K3520-Z is connected to the system.

udev finds a matching entry in /lib/udev/rules.d/40-usb_modeswitch.rules at line 565. That line is

ATTRS{idVendor}=="19d2", ATTRS{idProduct}=="2000", RUN+="usb_modeswitch '%b/%k'"

so udev runs

usb_modeswitch '7-1:1.0/7-1:1.0'

What /lib/udev/usb_modeswitch does in response to this invocation is not revealed by the entries in syslog. In theory it should run usb_modeswitch_dispatcher which should then run /usr/sbin/usb_modeswitch with parameters something like this:

usb_modeswitch --default-vendor 0x19d2 --default-product 0x2000 --message-content "5553424312345678000000000000061e000000000000000000000000000000" --message-content2="5553424312345679000000000000061b000000020000000000000000000000" --message-content3="55534243123456702000000080000c85010101180101010101000000000000" --need-response --target-vendor 0x19d2 --target-product 0x0055 -s 20 -D

but that is certainly not happening as the dongle remains in usb storage mode.

In my next comment I shall show the extract from syslog when I manually use usb_modeswitch to switch the dongle's mode.

[Dane Maslen (dane-maslen)]

The attached file is an extract from syslog that includes debug output from udev when I manually use usb_modeswitch to switch the K3520-Z's mode, i.e. when I issue the command

usb_modeswitch --default-vendor 0x19d2 --default-product 0x2000 --message-content "5553424312345678000000000000061e000000000000000000000000000000" --message-content2="5553424312345679000000000000061b000000020000000000000000000000" --message-content3="55534243123456702000000080000c85010101180101010101000000000000" --need-response --target-vendor 0x19d2 --target-product 0x0055 -s 20 -D

You will notice that initially there is a lot of activity removing the storage device that no longer exists. Then udev starts looking for rules for the new device. First it finds a matching entry in /lib/udev/rules.d/40-usb_modeswitch.rules at line 9. That line is

KERNEL=="ttyUSB*", ATTRS{bNumConfigurations}=="*", PROGRAM="usb_modeswitch --symlink-name %p %s{idVendor} %s{idProduct} %E{PRODUCT}", SYMLINK="%c"

Then it finds another matching entry in /lib/udev/rules.d/40-usb_modeswitch.rules at line 16. That line is

ATTR{bInterfaceClass}=="ff", ATTR{bInterfaceNumber}=="00", ATTRS{bNumConfigurations}=="*", RUN+="usb_modeswitch --driver-bind %p %s{idVendor} %s{idProduct} %E{PRODUCT}"

This is the rule that causes /lib/udev/usb_modeswitch to load the option driver if it not already loaded and to add the dongle to the devices managed by the option driver.

All of that activity would have appeared in the syslog extract in my previous comment if usb_modeswitch had successfully switched the dongle's mode at udev's instigation.

One other thing that you will find in the attached syslog extract is the following entry made by usb_modeswitch:

May 9 09:37:07 dell-desktop usb_modeswitch: switching device 19d2:2000 on 007/004

Bear this in mind when reading my next comment in which I shall show the extract from syslog that includes debug output from udev when the K3770 is connected to the system.

[Dane Maslen (dane-maslen)]

The attached file is an extract from syslog that includes debug output from udev when the K3770 is connected to the system.

Note that /lib/udev/rules.d/40-usb_modeswitch.rules line 397 is

ATTRS{idVendor}=="12d1", ATTRS{idProduct}=="14d1", RUN+="usb_modeswitch '%b/%k'"

This is the line that one would expect udev to match for this dongle, but it never happens. Instead the dongle switches mode for some other reason (I don't know what other reason, but I might eventually get round to investigating further) and then udev finds matching entry in /lib/udev/rules.d/40-usb_modeswitch.rules at lines 9 and 16 (cf my previous comment) for the new device. So the K3770 works correctly when connected to the system even though usb_modeswitch hasn't at any stage been invoked to switch its mode, as evidenced by the lack of a usb_modeswitch entry in syslog (cf my previous comment).

As a sanity check to confirm that usb_modeswitch was not responsible for the K3770 switching modes, I temporarily replaced /lib/udev/usb_modeswitch by a dummy shell script that did nothing more than 'exit 0' and then connected the K3770 to the system again. Despite the neutering of usb_modeswitch, the dongle still switched modes.

[Dane Maslen (dane-maslen)]

Having established that usb_modeswitch wasn't switching the K3520-Z's mode when invoked by udev to do so, and suspecting usb_modeswitch_dispatcher was to blame, I decided to write my own udev rules file (/etc/udev/rules.d/kludge_k3520z.rules) so as to bypass usb_modeswitch_dispatcher. It is attached. It causes udev to invoke a shell script (/lib/udev/kludge_k3520z) that runs usb_modeswitch with precisely those options required to switch the K3520-Z's mode.

[Dane Maslen (dane-maslen)]

Attached is /lib/udev/kludge_k3520z.

[Dane Maslen (dane-maslen)]

I had decided that the next thing to do was to try to get debug output from usb_modeswitch. In my efforts to find out how to do this I came across

  http://www.draisberghof.de/usb_modeswitch/#trouble

which includes a couple of notes about devices with ID 19d2:2000. The K3520-Z is one such device.

One of the notes is to the effect that newer kernels attempt to switch the mode of some devices and get it wrong for ID 19d2:2000, thereby messing things up for usb_modeswitch. I've no idea whether that is what is happening to me (if it is, then this is a kernel problem), but the revelation that the kernel switches the mode of some devices probably explains why my K3770 switches mode without usb_modeswitch getting involved.

[Dane Maslen (dane-maslen)]

I tried blacklisting the usb_storage module (as suggested by http://www.draisberghof.de/usb_modeswitch/#trouble) to see if this bug is caused by that kernel module. Unfortunately I then trip over this bug:

https://bugs.launchpad.net/ubuntu/+source/module-init-tools/+bug/1035739

which means that the blacklisting is ignored (to be precise the usb_storage module isn't loaded at boot but gets loaded as soon as any usb storage device is connected to the system). Great!

[Dane Maslen (dane-maslen)]

I've now ruled out kernel module usb_storage as the cause of the problem and have found that usb_modeswitch is failing to read device information even though lsusb shows me that the relevant information is available. I'm not familiar with device naming, but I can't see how /sys/bus/usb/devices/7-1:1.0 relates to the information I can get from lsusb. In particular lsusb refers to 'Bus 007 Device 004' while usb_modeswitch has been passed '7-1:1.0' by udev. Am I naïve in expecting to see a '4' somewhere in the parameter passed by udev?

I removed usb-storage.ko (by renaming it to out of the kernel directory tree), rebooted and tested both dongles. The K3520-Z behaved as before, i.e. it failed to switch modes. The K-3770 still worked, but checking udev debug output in syslog revealed that its mode was now being switched by usb_modeswitch rather than by the kernel module usb_storage.

My next step was to enable debug output in usb_modeswitch. It produced the following:

USB_ModeSwitch log from Fri May 10 17:48:11 2013

Using global config file: /etc/usb_modeswitch.conf

Raw args from udev: 7-1:1.0/7-1:1.0

Using top device dir /sys/bus/usb/devices/7-1:1.0

USB dir exists: /sys/bus/usb/devices/7-1:1.0
Warning: USB attribute "idVendor" not readable.
Warning: USB attribute "idProduct" not readable.
Warning: USB attribute "manufacturer" not readable.
Warning: USB attribute "product" not readable.
Warning: USB attribute "serial" not readable.
Warning: USB attribute "bNumConfigurations" not readable.
Warning: USB attribute "bConfigurationValue" not readable.
Warning: USB attribute "devnum" not readable.
Warning: USB attribute "busnum" not readable.

SCSI dir exists: /sys/bus/usb/devices/7-1:1.0
Warning: SCSI attribute "vendor" not readable.
Warning: SCSI attribute "model" not readable.
Warning: SCSI attribute "rev" not readable.
USB IDs not found in sysfs tree. Exiting.

So, basically usb_modeswitch (I think it's actually usb_modeswitch_dispatcher but I could be wrong) is failing to get any information about the device and hence can't look the device up in the usb_modeswitch_data tarball to find out the actions necessary to switch the mode.

The following is the output from lsusb --verbose -d 19d2:2000 and shows that the information that usb_modeswitch can't read is in fact available:

Bus 007 Device 004: ID 19d2:2000 ZTE WCDMA Technologies MSM MF627/MF628/MF628+/MF636+ HSDPA/HSUPA
Couldn't open device, some information will be missing
Device Descriptor:
  bLength 18
  bDescriptorType 1
  bcdUSB 1.10
  bDeviceClass 0 (Defined at Interface level)
  bDeviceSubClass 0
  bDeviceProtocol 0
  bMaxPacketSize0 64
  idVendor 0x19d2 ZTE WCDMA Technologies MSM
  idProduct 0x2000 MF627/MF628/MF628+/MF636+ HSDPA/HSUPA
  bcdDevice 0.00
  iManufacturer 1
  iProduct 2
  iSerial 3
  bNumConfigurations 1
  Configuration Descriptor:
    bLength 9
    bDescriptorType 2
    wTotalLength 32
    bNumInterfaces 1
    bConfigurationValue 1
    iConfiguration 0
    ...

[Dane Maslen (dane-maslen)]

I've pinned down the origin of the bug: the information being provided by udev to usb_modeswitch is not what usb_modeswitch is expecting. If my understanding of the udev documentation is correct, then there must be a bug in udev that is causing it to perform its %b substitution incorrectly. Only an examination of the udev code can reveal why this is happening.

Recall that the line in /lib/udev/rules.d/40-usb_modeswitch.rules that gets matched for the K3520-Z is

ATTRS{idVendor}=="19d2", ATTRS{idProduct}=="2000", RUN+="usb_modeswitch '%b/%k'"

The udev documentation states:

$id, %b
           The name of the device matched while searching the devpath upwards
           for SUBSYSTEMS, KERNELS, DRIVERS and ATTRS.

Thus for the above rule %b ought to be the name of the parent device for which idVendor is 19d2 and idProduct is 2000.

From an examination of the contents of /sys/bus/usb/devices I have been able to establish that the idVendor and idProduct files are in /sys/bus/usb/devices/7-1 so 7-1 is the device for which idVendor and idProduct matched. If, however, you look back at the debug output from usb_modeswitch you will see the following:

Raw args from udev: 7-1:1.0/7-1:1.0

i.e. udev has told usb_modeswitch that 7-1:1.0 was the device for which idVendor and idProduct matched. This misdirects usb_modeswitch into trying to read device data from /sys/bus/usb/devices/7-1:1.0 and as that directory does not contain idVendor and idProduct files, usb_modeswitch is unable to identify the vendor and product with the result that it can't work out how to switch the dongle's mode.

By once again renaming the kernel module usb-storage.ko out of the way to prevent it automatically switching the K3770's mode, I have been able to do the same analysis for the interaction between udev and usb_modeswitch for that dongle.

The line in /lib/udev/rules.d/40-usb_modeswitch.rules that gets matched for the K3770 is

ATTRS{idVendor}=="12d1", ATTRS{idProduct}=="14d1", RUN+="usb_modeswitch '%b/%k'"

so %b ought to be the name of the parent device for which idVendor is 12d1 and idProduct is 14d1. From an examination of the contents of /sys/bus/usb/devices it is evident that the idVendor and idProduct files are in /sys/bus/usb/devices/2-4 so 2-4 is the device for which idVendor and idProduct match. In this instance the debug output from usb_modeswitch starts

Raw args from udev: /2-4:1.0

Bus ID for device not given by udev.
 Trying to determine it from kernel name (2-4:1.0) ...
Using top device dir /sys/bus/usb/devices/2-4

Once again udev has failed to pass the correct name of the device for which idVendor and idProduct matched, but this time it has passed a null value rather than an incorrect one. Fortuitously usb_modeswitch seems to have code to cover this error, correctly deduces that the device directory to use is 2-4, and hence is able to read the idVendor and idProduct details successfully such that it can determine what steps are necessary to switch the dongle's mode.

And that's my last word on the subject (other than to answer my own question in the previous comment: I was indeed being naïve) for at least a month. If no one has shown any intere...