Bug 86611 - USB TO IDE Bridge stopped to work properly after kernel upgrade linux-3.12.21 -> linux-3.14.14
Summary: USB TO IDE Bridge stopped to work properly after kernel upgrade linux-3.12.21...
Status: NEW
Alias: None
Product: Drivers
Classification: Unclassified
Component: USB (show other bugs)
Hardware: All Linux
: P1 normal
Assignee: Greg Kroah-Hartman
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2014-10-20 21:26 UTC by Paul Osmialowski
Modified: 2014-11-14 15:04 UTC (History)
3 users (show)

See Also:
Kernel Version: 3.14.14, 3.16.6
Subsystem:
Regression: No
Bisected commit-id:


Attachments
usbmon logs and dmesgs (41.89 KB, application/octet-stream)
2014-10-25 18:58 UTC, Paul Osmialowski
Details
dmesg with usb storage debug (61.89 KB, text/plain)
2014-10-26 16:13 UTC, Paul Osmialowski
Details
Test for a skipped data phase in usb-storage (1.49 KB, patch)
2014-10-30 15:54 UTC, Alan Stern
Details | Diff
usbmon logs from patched 3.16.5 kernel, as requested (88.74 KB, text/plain)
2014-10-30 22:26 UTC, Paul Osmialowski
Details

Description Paul Osmialowski 2014-10-20 21:26:09 UTC
As in summary: 058f:6390 USB to IDE bridge is not working anymore.

On linux-3.12.21 dmesg says:

[  302.674422] hub 1-0:1.0: state 7 ports 8 chg 0000 evt 0010
[  302.674438] ehci-pci 0000:00:1d.7: GetStatus port:4 status 001002 0  ACK POWER sig=se0 CSC
[  302.674464] hub 1-0:1.0: port 4, status 0100, change 0001, 12 Mb/s
[  302.700011] ehci-pci 0000:00:1d.7: GetStatus port:4 status 001c03 0  ACK POWER sig=? CSC CONNECT
[  302.804017] hub 1-0:1.0: debounce: port 4: total 125ms stable 100ms status 0x501
[  302.855244] ehci-pci 0000:00:1d.7: port 4 reset complete, port enabled
[  302.855248] ehci-pci 0000:00:1d.7: GetStatus port:4 status 001005 0  ACK POWER sig=se0 PE CONNECT
[  302.906018] usb 1-4: new high-speed USB device number 5 using ehci-pci
[  305.083246] ehci-pci 0000:00:1d.7: port 4 reset complete, port enabled
[  305.083251] ehci-pci 0000:00:1d.7: GetStatus port:4 status 001005 0  ACK POWER sig=se0 PE CONNECT
[  307.272882] usb 1-4: default language 0x0409
[  307.273507] usb 1-4: udev 5, busnum 1, minor = 4
[  307.273511] usb 1-4: New USB device found, idVendor=058f, idProduct=6390
[  307.273515] usb 1-4: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[  307.273518] usb 1-4: Product: USB TO IDE Bridge
[  307.273520] usb 1-4: Manufacturer: Generic
[  307.273627] usb 1-4: usb_probe_device
[  307.273631] usb 1-4: configuration #1 chosen from 1 choice
[  307.273753] usb 1-4: adding 1-4:1.0 (config #1, interface 0)
[  307.273778] usb-storage 1-4:1.0: usb_probe_interface
[  307.273782] usb-storage 1-4:1.0: usb_probe_interface - got id
[  307.273785] usb-storage 1-4:1.0: USB Mass Storage device detected
[  307.275163] scsi9 : usb-storage 1-4:1.0
[  307.275274] hub 1-0:1.0: state 7 ports 8 chg 0000 evt 0010
[  329.811259] ehci-pci 0000:00:1d.7: port 4 reset complete, port enabled
[  329.811267] ehci-pci 0000:00:1d.7: GetStatus port:4 status 001005 0  ACK POWER sig=se0 PE CONNECT
[  329.862020] usb 1-4: reset high-speed USB device number 5 using ehci-pci
[  330.017254] ehci-pci 0000:00:1d.7: port 4 reset complete, port enabled
[  330.017259] ehci-pci 0000:00:1d.7: GetStatus port:4 status 001005 0  ACK POWER sig=se0 PE CONNECT
[  330.172408] scsi 9:0:0:0: Direct-Access     Generic  USB Disk         9.02 PQ: 0 ANSI: 2
[  330.172653] sd 9:0:0:0: Attached scsi generic sg6 type 0
[  330.173648] sd 9:0:0:0: [sdf] 976773168 512-byte logical blocks: (500 GB/465 GiB)
[  330.174641] sd 9:0:0:0: [sdf] Write Protect is off
[  330.174644] sd 9:0:0:0: [sdf] Mode Sense: 03 00 00 00
[  330.176027] sd 9:0:0:0: [sdf] No Caching mode page found
[  330.176030] sd 9:0:0:0: [sdf] Assuming drive cache: write through
[  330.181516] sd 9:0:0:0: [sdf] No Caching mode page found
[  330.181520] sd 9:0:0:0: [sdf] Assuming drive cache: write through
[  330.204155]  sdf: sdf1
[  330.207903] sd 9:0:0:0: [sdf] No Caching mode page found
[  330.207910] sd 9:0:0:0: [sdf] Assuming drive cache: write through
[  330.207914] sd 9:0:0:0: [sdf] Attached SCSI disk

On 3.14.14 it says:

[ 4280.846576] ehci-pci 0000:00:1d.7: GetStatus port:4 status 001003 0  ACK POWER sig=se0 CSC CONNECT
[ 4280.872016] ehci-pci 0000:00:1d.7: GetStatus port:4 status 001c03 0  ACK POWER sig=? CSC CONNECT
[ 4281.027259] ehci-pci 0000:00:1d.7: port 4 reset complete, port enabled
[ 4281.027263] ehci-pci 0000:00:1d.7: GetStatus port:4 status 001005 0  ACK POWER sig=se0 PE CONNECT
[ 4281.078020] usb 1-4: new high-speed USB device number 5 using ehci-pci
[ 4283.255265] ehci-pci 0000:00:1d.7: port 4 reset complete, port enabled
[ 4283.255275] ehci-pci 0000:00:1d.7: GetStatus port:4 status 001005 0  ACK POWER sig=se0 PE CONNECT
[ 4285.446403] usb 1-4: New USB device found, idVendor=058f, idProduct=6390
[ 4285.446410] usb 1-4: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[ 4285.446412] usb 1-4: Product: USB TO IDE Bridge
[ 4285.446414] usb 1-4: Manufacturer: Generic
[ 4285.446538] usb 1-4: usb_probe_device
[ 4285.446673] usb-storage 1-4:1.0: usb_probe_interface
[ 4285.446677] usb-storage 1-4:1.0: usb_probe_interface - got id
[ 4285.446681] usb-storage 1-4:1.0: USB Mass Storage device detected
[ 4285.447407] scsi9 : usb-storage 1-4:1.0
[ 4307.805273] ehci-pci 0000:00:1d.7: port 4 reset complete, port enabled
[ 4307.805282] ehci-pci 0000:00:1d.7: GetStatus port:4 status 001005 0  ACK POWER sig=se0 PE CONNECT
[ 4307.856022] usb 1-4: reset high-speed USB device number 5 using ehci-pci
[ 4308.018268] ehci-pci 0000:00:1d.7: port 4 reset complete, port enabled
[ 4308.018273] ehci-pci 0000:00:1d.7: GetStatus port:4 status 001005 0  ACK POWER sig=se0 PE CONNECT

And there's nothing after. I've found that on 3.14.14 scsi_probe_lun function does not result in following output:

sd 9:0:0:0: [sdf] 976773168 512-byte logical blocks: (500 GB/465 GiB)

which is the case for 3.12.21.

Also I tried Fedora with 3.16.6 - still USB TO IDE Bridge does not work properly.

Some time ago 058f:6390 was quite popular and I think it would be good to have it still supported (it is not listed as unusual device). I still have huge IDE disks with archive storage, it would be wasteful to throw them away.

Note that other usb-storage devices (smartphones, SD card readers) work for me properly with 3.14.14 and newer.
Comment 1 Alan Stern 2014-10-23 20:00:53 UTC
Please attach to this bug report a pair of usbmon traces, showing what happens when the drive is plugged in under 3.12 and under 3.14.  Instructions for usbmon can be found in the source file Documentation/usb/usbmon.txt.
Comment 2 Paul Osmialowski 2014-10-23 21:13:12 UTC
Hi,
Thanks for answer. I'll do that during the weekend.
Comment 3 Paul Osmialowski 2014-10-25 18:58:48 UTC
Created attachment 155091 [details]
usbmon logs and dmesgs

I've unplugged everything from usb bus 01, so only this device is there. Also I upgraded kernel on my box to 3.16.5 (still doesn't work), so attached logs are from three kernels: 3.12.21, 3.14.14 and 3.16.5
Comment 4 Alan Stern 2014-10-26 14:49:00 UTC
THe usbmon traces show that the device is a little buggy.  That's why you get those "reset high-speed USB device" messages under all the different kernel versions.

But in 3.12, the initialization proceeded after the reset and it worked correctly, whereas in 3.14 and 3.16 everything stopped after the reset.  I suspect this was caused by a bug in the SCSI layer.  You can help pin this down by rebuilding a 3.14 kernel with CONFIG_USB_STORAGE_DEBUG enabled; then the dmesg log will contain a lot more details.
Comment 5 Paul Osmialowski 2014-10-26 16:13:35 UTC
Created attachment 155231 [details]
dmesg with usb storage debug

As requiested, I'm attaching dmesgs with usb storage debug.

Note that to find out that I also added some printks and forced stack traces into scsi_probe_lun() function (despite the fact that diff shows that scsi_scan.c did not change between 3.12.21 and 3.14.14) and found differences in its action:
- 3.12.21:
[  124.159731] #### scsi_probe_lun
[  124.159735] CPU: 0 PID: 187 Comm: kworker/0:4 Tainted: P           O 3.12.21-gentoo-r1 #6
[  124.159736] Hardware name: Dell Inc. Precision WorkStation T5400  /0RW203, BIOS A05 09/09/2009
[  124.159744] Workqueue: events_freezable usb_stor_scan_dwork
[  124.159746]  0000000000000000 0000000000000000 ffffffff81b364a6 0000000000000000
[  124.159749]  ffffffff8160af56 ffff8801f03c95e0 0000000000000000 ffff880000000002
[  124.159751]  ffffffff81e77038 ffff8801f03da0e0 ffffffff81e77038 ffff8801f03c95c8
[  124.159753] Call Trace:
[  124.159765]  [<ffffffff81b364a6>] ? dump_stack+0x50/0x80
[  124.159773]  [<ffffffff8160af56>] ? scsi_probe_and_add_lun+0x136/0xd00
[  124.159776]  [<ffffffff8160bf95>] ? __scsi_scan_target+0x225/0x6a0
[  124.159780]  [<ffffffff815e356b>] ? rpm_resume+0xdb/0x6a0
[  124.159786]  [<ffffffff8109bc20>] ? call_timer_fn+0x170/0x170
[  124.159789]  [<ffffffff8160c46c>] ? scsi_scan_channel.part.8+0x5c/0x80
[  124.159791]  [<ffffffff8160c869>] ? scsi_scan_host_selected+0x119/0x1e0
[  124.159793]  [<ffffffff815e3dda>] ? __pm_runtime_resume+0x5a/0x80
[  124.159796]  [<ffffffff8160cb70>] ? scsi_scan_host+0x1a0/0x1f0
[  124.159798]  [<ffffffff816e4e27>] ? usb_stor_scan_dwork+0x47/0xf0
[  124.159803]  [<ffffffff810aa37d>] ? process_one_work+0x15d/0x430
[  124.159806]  [<ffffffff810aaa87>] ? worker_thread+0x117/0x370
[  124.159808]  [<ffffffff810aa970>] ? rescuer_thread+0x2e0/0x2e0
[  124.159811]  [<ffffffff810b10b8>] ? kthread+0xb8/0xc0
[  124.159814]  [<ffffffff810b0000>] ? SyS_timer_create+0xa0/0x4d0
[  124.159816]  [<ffffffff810b1000>] ? kthread_freezable_should_stop+0x60/0x60
[  124.159821]  [<ffffffff81b4556c>] ? ret_from_fork+0x7c/0xb0
[  124.159823]  [<ffffffff810b1000>] ? kthread_freezable_should_stop+0x60/0x60
[  124.159826] scsi 9:0:0:1: scsi scan: INQUIRY pass 1 length 36
[  124.159827] ==== count 0
[  124.161070] sd 9:0:0:0: [sdf] 976773168 512-byte logical blocks: (500 GB/465 GiB)
[  124.161132] scsi scan: INQUIRY failed with code 0x40000
  124.162188] sd 9:0:0:0: [sdf] Write Protect is off
[  124.162191] sd 9:0:0:0: [sdf] Mode Sense: 03 00 00 00
[  124.163191] sd 9:0:0:0: [sdf] No Caching mode page found
[  124.163193] sd 9:0:0:0: [sdf] Assuming drive cache: write through
[  124.166064] sd 9:0:0:0: [sdf] No Caching mode page found
[  124.166068] sd 9:0:0:0: [sdf] Assuming drive cache: write through
[  124.190581]  sdf: sdf1
[  124.194565] sd 9:0:0:0: [sdf] No Caching mode page found
[  124.194568] sd 9:0:0:0: [sdf] Assuming drive cache: write through
[  124.194571] sd 9:0:0:0: [sdf] Attached SCSI disk
[  135.837271] ehci-pci 0000:00:1d.7: port 4 reset complete, port enabled

- 3.14.14:
[  101.876211] #### scsi_probe_lun
[  101.876220] CPU: 1 PID: 35 Comm: kworker/1:1 Tainted: P           O 3.14.14-gentoo #16
[  101.876222] Hardware name: Dell Inc. Precision WorkStation T5400  /0RW203, BIOS A05 09/09/2009
[  101.876231] Workqueue: events_freezable usb_stor_scan_dwork
[  101.876234]  0000000000000000 0000000000000000 ffffffff81bb5791 0000000000000000
[  101.876237]  ffffffff8164112a ffff880226062040 ffff8801fe6b3438 ffff8801fe6b3438
[  101.876240]  0000000000000000 ffff8801fe6b3400 ffffffff8150d86d ffff8801fe6b34e0
[  101.876243] Call Trace:
[  101.876251]  [<ffffffff81bb5791>] ? dump_stack+0x49/0x6a
[  101.876256]  [<ffffffff8164112a>] ? scsi_probe_and_add_lun+0x16a/0xd40
[  101.876261]  [<ffffffff8150d86d>] ? kobject_set_name_vargs+0x4d/0x70
[  101.876265]  [<ffffffff816065d7>] ? dev_set_name+0x47/0x50
[  101.876269]  [<ffffffff8171d528>] ? target_alloc+0x28/0x70
[  101.876272]  [<ffffffff816062e7>] ? get_device+0x17/0x30
[  101.876276]  [<ffffffff81642056>] ? __scsi_scan_target+0x106/0x6c0
[  101.876279]  [<ffffffff81bba14d>] ? schedule_timeout+0x11d/0x230
[  101.876283]  [<ffffffff8161721b>] ? rpm_resume+0x19b/0x690
[  101.876287]  [<ffffffff8164266c>] ? scsi_scan_channel.part.8+0x5c/0x80
[  101.876290]  [<ffffffff81642a69>] ? scsi_scan_host_selected+0x119/0x1e0
[  101.876292]  [<ffffffff816179ba>] ? __pm_runtime_resume+0x5a/0x80
[  101.876295]  [<ffffffff81642d70>] ? scsi_scan_host+0x1a0/0x1f0
[  101.876299]  [<ffffffff8171f877>] ? usb_stor_scan_dwork+0x47/0xf0
[  101.876304]  [<ffffffff810afb6d>] ? process_one_work+0x15d/0x410
[  101.876307]  [<ffffffff810b07f6>] ? worker_thread+0x116/0x370
[  101.876310]  [<ffffffff810b06e0>] ? manage_workers.isra.25+0x290/0x290
[  101.876314]  [<ffffffff810b6b71>] ? kthread+0xc1/0xe0
[  101.876318]  [<ffffffff810c0000>] ? ftrace_raw_event_sched_process_wait+0x30/0x1b0
[  101.876322]  [<ffffffff810b6ab0>] ? kthread_freezable_should_stop+0x60/0x60
[  101.876326]  [<ffffffff81bc5d6c>] ? ret_from_fork+0x7c/0xb0
[  101.876329]  [<ffffffff810b6ab0>] ? kthread_freezable_should_stop+0x60/0x60
[  101.876334] scsi 9:0:0:0: scsi scan: INQUIRY pass 1 length 36
  101.876335] ==== count 0
[  122.781273] ehci-pci 0000:00:1d.7: port 4 reset complete, port enabled
[  122.781280] ehci-pci 0000:00:1d.7: GetStatus port:4 status 001005 0  ACK POWER sig=se0 PE CONNECT
[  122.832020] usb 1-4: reset high-speed USB device number 5 using ehci-pci
[  122.988268] ehci-pci 0000:00:1d.7: port 4 reset complete, port enabled
[  122.988272] ehci-pci 0000:00:1d.7: GetStatus port:4 status 001005 0  ACK POWER sig=se0 PE CONNECT
[  123.141679] scsi scan: INQUIRY failed with code 0x30000

scsi_probe_lun results in calling blk_execute_rq_nowait() from block/blk-exec.c. I'm not sure if it is important but what I see from the diffs is that drivers/scsi/* did not change much, however block/blk*.c changed alot.
Comment 6 Alan Stern 2014-10-28 18:11:19 UTC
The usb-storage debugging log confirms that the problem is in the SCSI layer.

And I have been able to reproduce the problem using a 3.17 kernel on my own computer.  I'll report back after I've had a chance to investigate it.
Comment 7 Alan Stern 2014-10-30 15:54:23 UTC
Created attachment 155871 [details]
Test for a skipped data phase in usb-storage

I haven't tracked down the exact reason for the regression, but it's probably a chance in drivers/scsi/scsi_error.c.

The attached patch ought to make a difference, although I don't know if it will solve your problem.  Please attach another usbmon trace showing what happens when you plug in the drive with a patched kernel.
Comment 8 Paul Osmialowski 2014-10-30 22:26:43 UTC
Created attachment 155901 [details]
usbmon logs from patched 3.16.5 kernel, as requested

Your patch works with 3.16.5 kernel. Now I can read partition table, mount partitions and use the disk as before! Thanks alot!
Comment 9 Alan Stern 2014-10-31 14:19:50 UTC
You're welcome.  I will submit the patch for inclusion in the kernel.
Comment 10 Alan Stern 2014-11-14 15:04:04 UTC
Fixed by commit 93c9bf4d1838d5851a18ca398b0ad66397f05056 (usb-storage: handle a skipped data phase).  This bug can be closed.

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