The C Source, Patches and (shudder!) Bugs
Post Reply
lkundrak
Posts: 24
Joined: 22 Jun 2016, 14:17

Nokia 0421:0637 won't switch

Post by lkundrak » 07 Sep 2016, 20:29

The device uses the StandardEject sequence. Nevertheless, it seems like it generally won't respond to the first message sent to it:

Code: Select all

[root@gsm-r5s9-01 ~# echo 3-6:1.0 >/sys/bus/usb/devices/3-6/3-6:1.0/driver/unbind; sleep 10
[root@gsm-r5s9-01 ~]# "/usr/sbin/usb_modeswitch" "-D" "-u -1" "-b 3" "-g 2" "-v" "0421" "-p" "0637" "-f" "$(echo -e "# Nokia CS-21M-02\nTargetVendor=0x0421\nTargetProduct=0x0638\nStandardEject=1\n")"
Use given bus/device number: 003/002 ...
Look for default devices ...
 bus/device number matched
   product ID matched
 Found devices in default mode (1)
Get the current device configuration ...
Use interface number 0
Use endpoints 0x01 (out) and 0x81 (in)

USB description data (for identification)
-------------------------
Manufacturer: Nokia
     Product: Nokia USB Modem
  Serial No.: 0.0.1
-------------------------
Sending standard EJECT sequence
Looking for active driver ...
 No active driver found. Detached before or never attached
Set up interface 0
Use endpoint 0x01 for message sending ...
Trying to send message 1 to endpoint 0x01 ...
 OK, message successfully sent
Read the response to message 1 (CSW) ...
 Response reading failed (error -7)
 Device is gone, skip any further commands
ok:busdev
[root@gsm-r5s9-01 ~]#
The second attempt proceeds just fine:

Code: Select all

[root@gsm-r5s9-01 ~]# "/usr/sbin/usb_modeswitch" "-D" "-u -1" "-b 3" "-g 2" "-v" "0421" "-p" "0637" "-f" "$(echo -e "# Nokia CS-21M-02\nTargetVendor=0x0421\nTargetProduct=0x0638\nStandardEject=1\n")"
Use given bus/device number: 003/002 ...
Look for default devices ...
 bus/device number matched
   product ID matched
 Found devices in default mode (1)
Get the current device configuration ...
Use interface number 0
Use endpoints 0x01 (out) and 0x81 (in)

USB description data (for identification)
-------------------------
Manufacturer: Nokia
     Product: Nokia USB Modem
  Serial No.: 0.0.1
-------------------------
Sending standard EJECT sequence
Looking for active driver ...
 No active driver found. Detached before or never attached
Set up interface 0
Use endpoint 0x01 for message sending ...
Trying to send message 1 to endpoint 0x01 ...
 OK, message successfully sent
Read the response to message 1 (CSW) ...
 Response successfully read (13 bytes), status 0
Trying to send message 2 to endpoint 0x01 ...
 OK, message successfully sent
Read the response to message 2 (CSW) ...
 Response successfully read (13 bytes), status 0
Trying to send message 3 to endpoint 0x01 ...
 OK, message successfully sent
Read the response to message 3 (CSW) ...
 Response successfully read (13 bytes), status 0
Trying to send message 4 to endpoint 0x01 ...
 OK, message successfully sent
Read the response to message 4 (CSW) ...
 Response successfully read (13 bytes), status 0
Reset response endpoint 0x81
Reset message endpoint 0x01
 Device is gone, skip any further commands
ok:busdev
[root@gsm-r5s9-01 ~]#
This sounds a lot like what's described here: http://www.draisberghof.de/usb_modeswit ... f=3&t=1955

The attached patch fixes the issue for me. Nevertheless, it's not exactly elegant.
Ideas about how to do this better appreciated.
Attachments
0001-switchSendMessage-retry-once-on-a-timeout.patch
(1.42 KiB) Downloaded 815 times

LOM
Posts: 1404
Joined: 11 Jul 2012, 15:14
Location: Koh Samui, TH

Re: Nokia 0421:0637 won't switch

Post by LOM » 08 Sep 2016, 07:53

Your problem is likely related to the modem not being stable on the usb bus.

The 4 messages behind StandardEject are:

to SCSI LUN 0
1. Unlock media (allow media removal)
2. Stop unit (eject media)

to SCSI LUN 1
3. Unlock media (allow media removal)
4. Stop unit (eject media)

The unlock cmd is only a preparation for eject (in case the cd-rom driver has issued a media lock) but it should not be able to cause the modem to fall off the bus as in your first log.
Your patch is not a fix, only a work-around, and I think we better find the reason why you get this kind of behaviour. CS21M has been supported for many years now and this is the first problem report I've seen for it..
What does your dmesg show from the usb activity?
Can you test if another distro behaves the same?
(Note that the similar problem you linked to was also using a Fedora distro).

Josh
Site Admin
Posts: 6570
Joined: 03 Nov 2007, 00:30

Re: Nokia 0421:0637 won't switch

Post by Josh » 08 Sep 2016, 08:03

lkundrak wrote:

Code: Select all

[root@gsm-r5s9-01 ~# echo 3-6:1.0 >/sys/bus/usb/devices/3-6/3-6:1.0/driver/unbind; sleep 10[/quote]
What happens if you leave out the "sleep" period? What happens if you leave out the unbind line altogether?

lkundrak
Posts: 24
Joined: 22 Jun 2016, 14:17

Re: Nokia 0421:0637 won't switch

Post by lkundrak » 08 Sep 2016, 12:09

LOM wrote:Your problem is likely related to the modem not being stable on the usb bus.
The unlock cmd is only a preparation for eject (in case the cd-rom driver has issued a media lock) but it should not be able to cause the modem to fall off the bus as in your first log.
Note the modem didn't fall off a bus -- that's merely imperfect wording in the error message. The real error there is "-7" which is a timeout.
LOM wrote: CS21M has been supported for many years now and this is the first problem report I've seen for it..
I think some older versions of usb_modeswitch & the data did things differently? Looking at usb-modeswitch-data-20130807, arguably quite ancient, shipped with RHEL 7.2 does this instead of aj eject:

MessageContent="5553424312345678000000000000061b000000020000000000000000000000"
LOM wrote: What does your dmesg show from the usb activity?
Nothing at all. (I guess you expected something here because you assumed the device actually dropped off the bus?)
LOM wrote: Can you test if another distro behaves the same?
(Note that the similar problem you linked to was also using a Fedora distro).
Unfortunately not. I don't have a physical access to the machine nor an access to the firmware console.
Josh wrote:
lkundrak wrote:

Code: Select all

[root@gsm-r5s9-01 ~# echo 3-6:1.0 >/sys/bus/usb/devices/3-6/3-6:1.0/driver/unbind; sleep 10[/quote]
What happens if you leave out the "sleep" period? What happens if you leave out the unbind line altogether?[/quote]

No effect, the same symptoms.

I just left that in place to ensure the unbinding didn't interfere with the switch.

lkundrak
Posts: 24
Joined: 22 Jun 2016, 14:17

Re: Nokia 0421:0637 won't switch

Post by lkundrak » 08 Sep 2016, 12:11

LOM wrote:What does your dmesg show from the usb activity?
Oh, sorry, there actually is something.

When the kernel driver binds:

Code: Select all

[    3.902716] sr 0:0:0:0: [sr1] scsi3-mmc drive: 0x/0x caddy
[    3.908377] sr 0:0:0:0: Attached scsi CD-ROM sr1
[    3.909234] sd 0:0:0:1: [sdb] Attached SCSI removable disk
[    3.969474] sr 0:0:0:0: [sr1] CDROM (ioctl) error, command: Xpwrite, Read disk info 51 00 00 00 00 00 00 00 02 00
[    3.979911] sr 0:0:0:0: [sr1] Sense Key : Hardware Error [current] 
[    3.986284] sr 0:0:0:0: [sr1] Add. Sense: No additional sense information
And when the kernel driver is unbound:

Code: Select all

[   66.749050] sr 0:0:0:0: [sr1] CDROM (ioctl) error, command: Xpwrite, Read disk info 51 00 00 00 00 00 00 00 02 00
[   66.873062] sr 0:0:0:0: [sr1] Sense Key : Hardware Error [current] 
[   66.949329] sr 0:0:0:0: [sr1] Add. Sense: No additional sense information

LOM
Posts: 1404
Joined: 11 Jul 2012, 15:14
Location: Koh Samui, TH

Re: Nokia 0421:0637 won't switch

Post by LOM » 08 Sep 2016, 14:52

What kind of hardware is the host, a very fast computer?
Hopefully not a Raspberry Pi..

lkundrak
Posts: 24
Joined: 22 Jun 2016, 14:17

Re: Nokia 0421:0637 won't switch

Post by lkundrak » 08 Sep 2016, 16:04

LOM wrote:What kind of hardware is the host, a very fast computer?
Hopefully not a Raspberry Pi..
According to the DMI it's a ThinkCentre M73 with BIOS dated 12/2015. Doesn't seem like an old machine.
Has a 4th i3-4150 CPU and the phone is plugged into an USB 2.0 port of "Intel Corporation 8 Series/C220 Series Chipset".

LOM
Posts: 1404
Joined: 11 Jul 2012, 15:14
Location: Koh Samui, TH

Re: Nokia 0421:0637 won't switch

Post by LOM » 09 Sep 2016, 11:44

lkundrak wrote:
LOM wrote:Your problem is likely related to the modem not being stable on the usb bus.
The unlock cmd is only a preparation for eject (in case the cd-rom driver has issued a media lock) but it should not be able to cause the modem to fall off the bus as in your first log.
Note the modem didn't fall off a bus -- that's merely imperfect wording in the error message. The real error there is "-7" which is a timeout.
Right.

lkundrak wrote:
LOM wrote: CS21M has been supported for many years now and this is the first problem report I've seen for it..
I think some older versions of usb_modeswitch & the data did things differently? Looking at usb-modeswitch-data-20130807, arguably quite ancient, shipped with RHEL 7.2 does this instead of aj eject:

MessageContent="5553424312345678000000000000061b000000020000000000000000000000"

It might be that the urb which we don't get the status reply for is accepted by the modem.
The previous switch method was a single eject msg which would switch the dongle while the new dual msg will only get the first prepare msg through.

lkundrak wrote:
LOM wrote:What does your dmesg show from the usb activity?
Oh, sorry, there actually is something.

When the kernel driver binds:

Code: Select all

[    3.902716] sr 0:0:0:0: [sr1] scsi3-mmc drive: 0x/0x caddy
[    3.908377] sr 0:0:0:0: Attached scsi CD-ROM sr1
[    3.909234] sd 0:0:0:1: [sdb] Attached SCSI removable disk
[    3.969474] sr 0:0:0:0: [sr1] CDROM (ioctl) error, command: Xpwrite, Read disk info 51 00 00 00 00 00 00 00 02 00
[    3.979911] sr 0:0:0:0: [sr1] Sense Key : Hardware Error [current] 
[    3.986284] sr 0:0:0:0: [sr1] Add. Sense: No additional sense information
And when the kernel driver is unbound:

Code: Select all

[   66.749050] sr 0:0:0:0: [sr1] CDROM (ioctl) error, command: Xpwrite, Read disk info 51 00 00 00 00 00 00 00 02 00
[   66.873062] sr 0:0:0:0: [sr1] Sense Key : Hardware Error [current] 
[   66.949329] sr 0:0:0:0: [sr1] Add. Sense: No additional sense information

Is indicative of something wrong with the virtual cd-rom, it is either partially destroyed or very slow, it is probably also the reason why we don't get a status reply for our first cmd within time.

I think we may get that reply if we only wait long enough for it, can you try to add a delay instead of doing a retry? 100mS could be a reasonable value.

lkundrak
Posts: 24
Joined: 22 Jun 2016, 14:17

Re: Nokia 0421:0637 won't switch

Post by lkundrak » 09 Sep 2016, 16:49

LOM wrote:I think we may get that reply if we only wait long enough for it, can you try to add a delay instead of doing a retry? 100mS could be a reasonable value.
The current timeout is 3 seconds. I've previously tried to raise it to 30 seconds, but that didn't change anything.

LOM
Posts: 1404
Joined: 11 Jul 2012, 15:14
Location: Koh Samui, TH

Re: Nokia 0421:0637 won't switch

Post by LOM » 09 Sep 2016, 17:34

lkundrak wrote:
LOM wrote:I think we may get that reply if we only wait long enough for it, can you try to add a delay instead of doing a retry? 100mS could be a reasonable value.
The current timeout is 3 seconds. I've previously tried to raise it to 30 seconds, but that didn't change anything.
I don't think we are talking about the same thing, I'd like to have a delay between sending a message and checking the status reply for that message.
usb in a nutshell wrote: A USB compliant Host expects all requests to be processed within a maximum period of 5 seconds. It also specifies stricter timing for specific requests :

Standard Device requests without a data stage must be completed in 50ms.

Standard Device requests with a data stage must start to return data 500ms after the request.
Each data packet must be sent within 500ms of the successful transmission of the previous packet.
The status stage must complete within 50ms after the transmission of the last data packet.

The SetAddress command (which contains a data phase) must process the command and return status within 50ms. The device then has 2ms to change address before the next request is sent.
"unlock media" is not in the list over Standard Device requests and I don't find it unreasonable that it could take longer than 50mS to grant an unlock if the cd-rom is busy.

If it really is so that we never get that status reply, that we need an extra dummy message in order to wake up the device then it is surely a device firmware bug which shouldn't be fixed by usb_modeswitch.
It would also explain the inability for the cd-rom driver to "read disk info"....

lkundrak
Posts: 24
Joined: 22 Jun 2016, 14:17

Re: Nokia 0421:0637 won't switch

Post by lkundrak » 12 Sep 2016, 14:22

LOM wrote:
lkundrak wrote:
LOM wrote:I think we may get that reply if we only wait long enough for it, can you try to add a delay instead of doing a retry? 100mS could be a reasonable value.
The current timeout is 3 seconds. I've previously tried to raise it to 30 seconds, but that didn't change anything.
I don't think we are talking about the same thing, I'd like to have a delay between sending a message and checking the status reply for that message.
Ah, ok. Tried that as well now, nothing changed :(
LOM wrote:
usb in a nutshell wrote: A USB compliant Host expects all requests to be processed within a maximum period of 5 seconds. It also specifies stricter timing for specific requests :

Standard Device requests without a data stage must be completed in 50ms.

Standard Device requests with a data stage must start to return data 500ms after the request.
Each data packet must be sent within 500ms of the successful transmission of the previous packet.
The status stage must complete within 50ms after the transmission of the last data packet.

The SetAddress command (which contains a data phase) must process the command and return status within 50ms. The device then has 2ms to change address before the next request is sent.
"unlock media" is not in the list over Standard Device requests and I don't find it unreasonable that it could take longer than 50mS to grant an unlock if the cd-rom is busy.

If it really is so that we never get that status reply, that we need an extra dummy message in order to wake up the device then it is surely a device firmware bug which shouldn't be fixed by usb_modeswitch.
It would also explain the inability for the cd-rom driver to "read disk info"....
Dan Williams reported that his phone switches correctly with Fedora 23. I've tried the latest kernel tip on the machine where I can reproduce the problem -- the error messages from the CD-ROM driver is gone, but the problem is still there.

lkundrak
Posts: 24
Joined: 22 Jun 2016, 14:17

Re: Nokia 0421:0637 won't switch

Post by lkundrak » 12 Sep 2016, 14:29

Hmm, blacklisting sr_mod and cdrom modules fixes the issue.
Need to look into what do they do.

lkundrak
Posts: 24
Joined: 22 Jun 2016, 14:17

Re: Nokia 0421:0637 won't switch

Post by lkundrak » 18 Aug 2017, 10:43

Looked a bit further into the issue.

The phone misbehaves (ignores one message) in most cases when the endpoint is reset prior to issuing the allow remove (0x1e) command.
It doesn't seem to happen when the one of the few commands preceding the reset is test unit ready (0x00) which explains why it worked sometimes.

It is obvious now that this is a hardware/firmware (we can't fix) issue and there's perhaps not too much a kernel could do either.
I guess the best idea would be to only issue the endpoint reset when we're positive that the endpoint is in a stall condition? (patch attached)
Attachments
0001-usb_modeswitch-don-t-reset-an-endpoint-unless-stalle.patch
(1.88 KiB) Downloaded 817 times

lkundrak
Posts: 24
Joined: 22 Jun 2016, 14:17

Re: Nokia 0421:0637 won't switch

Post by lkundrak » 18 Aug 2017, 10:53

Sorry for the bump.
Seems like this one has been silently applied and thus the issue is resolved.

Josh
Site Admin
Posts: 6570
Joined: 03 Nov 2007, 00:30

Re: Nokia 0421:0637 won't switch

Post by Josh » 18 Aug 2017, 14:06

Well, don't know about "silently" ... :)

http://draisberghof.de/usb_modeswitch/b ... hp?p=17382

(Also in the official ChangeLog)

Post Reply