[2.6.30-rc2] usb reset during big file transfer and ext3 error

[2.6.30-rc2] usb reset during big file transfer and ext3 error

[Rogério Brito]

[-- Attachment #1: Type: text/plain, Size: 1195 bytes --]

Hi there.

I have an amd64 system running Debian's sid distribution and I installed
Linux 2.6.30-rc2 on it, as a way to get improvements for the i915
subsystem.

Unfortunately, when I was transferring the contents of 2 DVDs from the
main IDE HD to a USB external HD, I got errors from the USB host, the
writes on the external HD become failures and the ext3 filesystem there
enters into error mode, going read-only.

I eventually lose the access to the device (i.e., the /dev/sd??? device
isn't there anymore) and I then have to re-run fsck on the given
filesystem.

This has already happened 2 or 3 times already and I observed that it
only occurs when there is high traffic---if I am, say, compiling the
kernel on that external HD, I don't see any problems.

Attached is part of the dmesg log that shows the problem. I put the
whole dmesg at <http://rb.doesntexist.org/linux/>.

As always, if any further information is needed, please let me know.


Thanks, Rogério Brito.

-- 
Rogério Brito : rbrito@{mackenzie,ime.usp}.br : GPG key 1024D/7C2CAEB8
http://www.ime.usp.br/~rbrito : http://meusite.mackenzie.com.br/rbrito
Projects: algorithms.berlios.de : lame.sf.net : vrms.alioth.debian.org

[-- Attachment #2: dmesg-usb-reset-and-ext3-error.txt --]
[-- Type: text/plain, Size: 29034 bytes --]

[ 2549.248657] [drm] Initialized drm 1.1.0 20060810
[ 2549.274952] pci 0000:00:02.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16
[ 2549.274966] pci 0000:00:02.0: setting latency timer to 64
[ 2549.284965] [drm] Initialized i915 1.6.0 20080730 for 0000:00:02.0 on minor 0
[ 2637.993156] [drm:i915_get_vblank_counter] *ERROR* trying to get vblank count for disabled pipe 1
[ 2638.160324] [drm:i915_get_vblank_counter] *ERROR* trying to get vblank count for disabled pipe 1
[ 4433.904183] kjournald starting.  Commit interval 5 seconds
[ 4433.905842] EXT3 FS on sda1, internal journal
[ 4433.905857] EXT3-fs: mounted filesystem with writeback data mode.
[53869.272136] RPC: Registered udp transport module.
[53869.272143] RPC: Registered tcp transport module.
[53869.335615] Slow work thread pool: Starting up
[53869.335792] Slow work thread pool: Ready
[53869.335876] FS-Cache: Loaded
[53869.427746] FS-Cache: Netfs 'nfs' registered for caching
[79423.834543] TCP(fetchmail:17649): Application bug, race in MSG_PEEK.
[86492.830164] hub 1-0:1.0: state 7 ports 8 chg 0000 evt 0004
[86492.830186] ehci_hcd 0000:00:1d.7: GetStatus port 2 status 001803 POWER sig=j CSC CONNECT
[86492.830201] hub 1-0:1.0: port 2, status 0501, change 0001, 480 Mb/s
[86492.935048] hub 1-0:1.0: debounce: port 2: total 100ms stable 100ms status 0x501
[86492.987231] ehci_hcd 0000:00:1d.7: port 2 full speed --> companion
[86492.987240] ehci_hcd 0000:00:1d.7: GetStatus port 2 status 003801 POWER OWNER sig=j CONNECT
[86492.987272] hub 1-0:1.0: port 2 not reset yet, waiting 50ms
[86492.987283] usb usb2: usb resume
[86492.987286] usb usb2: wakeup_rh
[86493.019783] hub 2-0:1.0: hub_resume
[86493.019813] uhci_hcd 0000:00:1d.0: port 2 portsc 0093,00
[86493.019819] hub 2-0:1.0: port 2: status 0101 change 0001
[86493.039050] ehci_hcd 0000:00:1d.7: GetStatus port 2 status 003002 POWER OWNER sig=se0 CSC
[86493.039095] hub 1-0:1.0: state 7 ports 8 chg 0000 evt 0004
[86493.121258] hub 2-0:1.0: state 7 ports 2 chg 0004 evt 0000
[86493.121286] hub 2-0:1.0: port 2, status 0101, change 0000, 12 Mb/s
[86493.224022] usb 2-2: new full speed USB device using uhci_hcd and address 2
[86493.346010] usb 2-2: ep0 maxpacket = 8
[86493.392973] usb 2-2: default language 0x0409
[86493.414991] usb 2-2: New USB device found, idVendor=03f0, idProduct=4811
[86493.415000] usb 2-2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[86493.415018] usb 2-2: Product: PSC 1600 series
[86493.415022] usb 2-2: Manufacturer: HP
[86493.415025] usb 2-2: SerialNumber: BR64SDP097L0
[86493.415208] usb 2-2: uevent
[86493.415244] usb 2-2: usb_probe_device
[86493.415250] usb 2-2: configuration #1 chosen from 1 choice
[86493.418188] usb 2-2: adding 2-2:1.0 (config #1, interface 0)
[86493.418274] usb 2-2:1.0: uevent
[86493.418704] usb 2-2: adding 2-2:1.1 (config #1, interface 1)
[86493.418773] usb 2-2:1.1: uevent
[86493.419127] usb 2-2: adding 2-2:1.2 (config #1, interface 2)
[86493.419177] usb 2-2:1.2: uevent
[86493.419493] usb 2-2: adding 2-2:1.3 (config #1, interface 3)
[86493.419542] usb 2-2:1.3: uevent
[86493.419576] usb-storage 2-2:1.3: usb_probe_interface
[86493.419584] usb-storage 2-2:1.3: usb_probe_interface - got id
[86493.432978] scsi1 : SCSI emulation for USB Mass Storage devices
[86493.433973] drivers/usb/core/inode.c: creating file '002'
[86493.434475] usb-storage: device found at 2
[86493.434479] usb-storage: waiting for device to settle before scanning
[86493.600758] usblp 2-2:1.1: usb_probe_interface
[86493.600764] usblp 2-2:1.1: usb_probe_interface - got id
[86493.604982] drivers/usb/core/file.c: looking for a minor, starting at 0
[86493.605216] usblp0: USB Bidirectional printer dev 2 if 1 alt 0 proto 2 vid 0x03F0 pid 0x4811
[86493.605278] usbcore: registered new interface driver usblp
[86498.436129] usb-storage: device scan complete
[86498.439106] scsi 1:0:0:0: Direct-Access     HP       PSC 1610         1.00 PQ: 0 ANSI: 2
[86498.468856] sd 1:0:0:0: [sdb] Attached SCSI removable disk
[86498.549340] usb 2-2:1.3: uevent
[86498.549701] usb 2-2: uevent
[86512.705044] hub 2-0:1.0: state 7 ports 2 chg 0000 evt 0004
[86512.705062] uhci_hcd 0000:00:1d.0: port 2 portsc 008a,00
[86512.705080] hub 2-0:1.0: port 2, status 0100, change 0003, 12 Mb/s
[86512.705086] usb 2-2: USB disconnect, address 2
[86512.705091] usb 2-2: unregistering device
[86512.705095] usb 2-2: usb_disable_device nuking all URBs
[86512.705111] usb 2-2: unregistering interface 2-2:1.0
[86512.705502] usb 2-2:1.0: uevent
[86512.705534] usb 2-2: unregistering interface 2-2:1.1
[86512.705824] drivers/usb/core/file.c: removing 0 minor
[86512.705944] usblp0: removed
[86512.705971] usb 2-2:1.1: uevent
[86512.705996] usb 2-2: unregistering interface 2-2:1.2
[86512.706317] usb 2-2:1.2: uevent
[86512.706342] usb 2-2: unregistering interface 2-2:1.3
[86512.712318] usb 2-2:1.3: uevent
[86512.712734] usb 2-2: uevent
[86512.817029] hub 2-0:1.0: debounce: port 2: total 100ms stable 100ms status 0x100
[86513.955019] usb usb2: suspend_rh (auto-stop)
[86515.705093] hub 2-0:1.0: hub_suspend
[86515.705108] usb usb2: bus auto-suspend
[86515.705112] usb usb2: suspend_rh
[103051.265045] ehci_hcd 0000:00:1d.7: detected XactErr len 1536/4096 retry 1
[103051.265156] ehci_hcd 0000:00:1d.7: detected XactErr len 1536/4096 retry 2
[103051.265281] ehci_hcd 0000:00:1d.7: detected XactErr len 1536/4096 retry 3
[103051.265406] ehci_hcd 0000:00:1d.7: detected XactErr len 1536/4096 retry 4
[103051.265531] ehci_hcd 0000:00:1d.7: detected XactErr len 1536/4096 retry 5
[103051.265656] ehci_hcd 0000:00:1d.7: detected XactErr len 1536/4096 retry 6
[103051.265781] ehci_hcd 0000:00:1d.7: detected XactErr len 1536/4096 retry 7
[103051.265906] ehci_hcd 0000:00:1d.7: detected XactErr len 1536/4096 retry 8
[103051.266032] ehci_hcd 0000:00:1d.7: detected XactErr len 1536/4096 retry 9
[103051.266157] ehci_hcd 0000:00:1d.7: detected XactErr len 1536/4096 retry 10
[103051.266281] ehci_hcd 0000:00:1d.7: detected XactErr len 1536/4096 retry 11
[103051.266406] ehci_hcd 0000:00:1d.7: detected XactErr len 1536/4096 retry 12
[103051.266530] ehci_hcd 0000:00:1d.7: detected XactErr len 1536/4096 retry 13
[103051.266655] ehci_hcd 0000:00:1d.7: detected XactErr len 1536/4096 retry 14
[103051.266781] ehci_hcd 0000:00:1d.7: detected XactErr len 1536/4096 retry 15
[103051.266906] ehci_hcd 0000:00:1d.7: detected XactErr len 1536/4096 retry 16
[103051.267032] ehci_hcd 0000:00:1d.7: detected XactErr len 1536/4096 retry 17
[103051.267155] ehci_hcd 0000:00:1d.7: detected XactErr len 1536/4096 retry 18
[103051.267281] ehci_hcd 0000:00:1d.7: detected XactErr len 1536/4096 retry 19
[103051.267406] ehci_hcd 0000:00:1d.7: detected XactErr len 1536/4096 retry 20
[103051.267530] ehci_hcd 0000:00:1d.7: detected XactErr len 1536/4096 retry 21
[103051.267655] ehci_hcd 0000:00:1d.7: detected XactErr len 1536/4096 retry 22
[103051.267782] ehci_hcd 0000:00:1d.7: detected XactErr len 1536/4096 retry 23
[103051.267906] ehci_hcd 0000:00:1d.7: detected XactErr len 1536/4096 retry 24
[103051.268031] ehci_hcd 0000:00:1d.7: detected XactErr len 1536/4096 retry 25
[103051.268155] ehci_hcd 0000:00:1d.7: detected XactErr len 1536/4096 retry 26
[103051.268280] ehci_hcd 0000:00:1d.7: detected XactErr len 1536/4096 retry 27
[103051.268406] ehci_hcd 0000:00:1d.7: detected XactErr len 1536/4096 retry 28
[103051.268537] ehci_hcd 0000:00:1d.7: detected XactErr len 1536/4096 retry 29
[103051.268659] ehci_hcd 0000:00:1d.7: detected XactErr len 1536/4096 retry 30
[103051.268780] ehci_hcd 0000:00:1d.7: detected XactErr len 1536/4096 retry 31
[103051.268905] ehci_hcd 0000:00:1d.7: devpath 6.1 ep2out 3strikes
[103051.280918] hub 1-6:1.0: logical disconnect on port 1
[103051.281235] sd 0:0:0:0: [sda] Unhandled error code
[103051.281241] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.281247] end_request: I/O error, dev sda, sector 255674535
[103051.281254] Buffer I/O error on device sda1, logical block 31959309
[103051.281257] lost page write due to I/O error on sda1
[103051.281269] Buffer I/O error on device sda1, logical block 31959310
[103051.281273] lost page write due to I/O error on sda1
[103051.281279] Buffer I/O error on device sda1, logical block 31959311
[103051.281282] lost page write due to I/O error on sda1
[103051.281294] Buffer I/O error on device sda1, logical block 31959312
[103051.281297] lost page write due to I/O error on sda1
[103051.281303] Buffer I/O error on device sda1, logical block 31959313
[103051.281306] lost page write due to I/O error on sda1
[103051.281311] Buffer I/O error on device sda1, logical block 31959314
[103051.281315] lost page write due to I/O error on sda1
[103051.281320] Buffer I/O error on device sda1, logical block 31959315
[103051.281323] lost page write due to I/O error on sda1
[103051.281329] Buffer I/O error on device sda1, logical block 31959316
[103051.281332] lost page write due to I/O error on sda1
[103051.281337] Buffer I/O error on device sda1, logical block 31959317
[103051.281341] lost page write due to I/O error on sda1
[103051.281346] Buffer I/O error on device sda1, logical block 31959318
[103051.281349] lost page write due to I/O error on sda1
[103051.281474] sd 0:0:0:0: [sda] Unhandled error code
[103051.281478] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.281483] end_request: I/O error, dev sda, sector 255674775
[103051.281624] sd 0:0:0:0: [sda] Unhandled error code
[103051.281627] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.281633] end_request: I/O error, dev sda, sector 255675015
[103051.281778] sd 0:0:0:0: [sda] Unhandled error code
[103051.281781] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.281786] end_request: I/O error, dev sda, sector 255675255
[103051.281928] sd 0:0:0:0: [sda] Unhandled error code
[103051.281931] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.281936] end_request: I/O error, dev sda, sector 255675495
[103051.282076] sd 0:0:0:0: [sda] Unhandled error code
[103051.282079] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.282084] end_request: I/O error, dev sda, sector 255675735
[103051.282215] sd 0:0:0:0: [sda] Unhandled error code
[103051.282218] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.282223] end_request: I/O error, dev sda, sector 255675975
[103051.282340] sd 0:0:0:0: [sda] Unhandled error code
[103051.282343] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.282348] end_request: I/O error, dev sda, sector 255676215
[103051.282467] sd 0:0:0:0: [sda] Unhandled error code
[103051.282470] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.282476] end_request: I/O error, dev sda, sector 255676455
[103051.282613] sd 0:0:0:0: [sda] Unhandled error code
[103051.282617] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.282622] end_request: I/O error, dev sda, sector 255676695
[103051.282764] sd 0:0:0:0: [sda] Unhandled error code
[103051.282767] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.282772] end_request: I/O error, dev sda, sector 255676935
[103051.282900] sd 0:0:0:0: [sda] Unhandled error code
[103051.282903] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.282908] end_request: I/O error, dev sda, sector 255677175
[103051.283076] sd 0:0:0:0: [sda] Unhandled error code
[103051.283080] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.283085] end_request: I/O error, dev sda, sector 255677415
[103051.283218] sd 0:0:0:0: [sda] Unhandled error code
[103051.283222] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.283227] end_request: I/O error, dev sda, sector 255677655
[103051.283368] sd 0:0:0:0: [sda] Unhandled error code
[103051.283371] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.283376] end_request: I/O error, dev sda, sector 255677895
[103051.283501] sd 0:0:0:0: [sda] Unhandled error code
[103051.283504] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.283509] end_request: I/O error, dev sda, sector 255678135
[103051.283640] sd 0:0:0:0: [sda] Unhandled error code
[103051.283643] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.283648] end_request: I/O error, dev sda, sector 255678375
[103051.283728] sd 0:0:0:0: [sda] Unhandled error code
[103051.283731] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.283736] end_request: I/O error, dev sda, sector 255678415
[103051.283863] sd 0:0:0:0: [sda] Unhandled error code
[103051.283866] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.283871] end_request: I/O error, dev sda, sector 255678655
[103051.283992] sd 0:0:0:0: [sda] Unhandled error code
[103051.283996] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.284006] end_request: I/O error, dev sda, sector 255678895
[103051.284134] sd 0:0:0:0: [sda] Unhandled error code
[103051.284138] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.284143] end_request: I/O error, dev sda, sector 255679135
[103051.284273] sd 0:0:0:0: [sda] Unhandled error code
[103051.284276] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.284281] end_request: I/O error, dev sda, sector 255679375
[103051.284409] sd 0:0:0:0: [sda] Unhandled error code
[103051.284413] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.284418] end_request: I/O error, dev sda, sector 255679615
[103051.284568] sd 0:0:0:0: [sda] Unhandled error code
[103051.284572] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.284577] end_request: I/O error, dev sda, sector 255679855
[103051.284717] sd 0:0:0:0: [sda] Unhandled error code
[103051.284721] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.284726] end_request: I/O error, dev sda, sector 255680095
[103051.284866] sd 0:0:0:0: [sda] Unhandled error code
[103051.284870] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.284875] end_request: I/O error, dev sda, sector 255680335
[103051.285007] sd 0:0:0:0: [sda] Unhandled error code
[103051.285010] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.285015] end_request: I/O error, dev sda, sector 255680575
[103051.285157] sd 0:0:0:0: [sda] Unhandled error code
[103051.285160] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.285165] end_request: I/O error, dev sda, sector 255680815
[103051.285294] sd 0:0:0:0: [sda] Unhandled error code
[103051.285298] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.285303] end_request: I/O error, dev sda, sector 255681055
[103051.285425] sd 0:0:0:0: [sda] Unhandled error code
[103051.285429] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.285434] end_request: I/O error, dev sda, sector 255681295
[103051.285552] sd 0:0:0:0: [sda] Unhandled error code
[103051.285556] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.285561] end_request: I/O error, dev sda, sector 255681535
[103051.285687] sd 0:0:0:0: [sda] Unhandled error code
[103051.285691] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.285696] end_request: I/O error, dev sda, sector 255681775
[103051.285833] sd 0:0:0:0: [sda] Unhandled error code
[103051.285837] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.285842] end_request: I/O error, dev sda, sector 255682015
[103051.285983] sd 0:0:0:0: [sda] Unhandled error code
[103051.285987] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.285992] end_request: I/O error, dev sda, sector 255682255
[103051.286125] sd 0:0:0:0: [sda] Unhandled error code
[103051.286128] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.286133] end_request: I/O error, dev sda, sector 255682495
[103051.286265] sd 0:0:0:0: [sda] Unhandled error code
[103051.286268] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.286273] end_request: I/O error, dev sda, sector 255682735
[103051.286391] sd 0:0:0:0: [sda] Unhandled error code
[103051.286394] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.286399] end_request: I/O error, dev sda, sector 255682975
[103051.286538] sd 0:0:0:0: [sda] Unhandled error code
[103051.286541] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.286546] end_request: I/O error, dev sda, sector 255683215
[103051.286684] sd 0:0:0:0: [sda] Unhandled error code
[103051.286688] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.286693] end_request: I/O error, dev sda, sector 255683455
[103051.286822] sd 0:0:0:0: [sda] Unhandled error code
[103051.286825] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.286830] end_request: I/O error, dev sda, sector 255683695
[103051.286948] sd 0:0:0:0: [sda] Unhandled error code
[103051.286951] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.286956] end_request: I/O error, dev sda, sector 255683935
[103051.287092] sd 0:0:0:0: [sda] Unhandled error code
[103051.287095] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.287100] end_request: I/O error, dev sda, sector 255684175
[103051.287225] sd 0:0:0:0: [sda] Unhandled error code
[103051.287228] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.287233] end_request: I/O error, dev sda, sector 255684415
[103051.287382] sd 0:0:0:0: [sda] Unhandled error code
[103051.287386] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.287391] end_request: I/O error, dev sda, sector 255684655
[103051.287540] sd 0:0:0:0: [sda] Unhandled error code
[103051.287543] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.287548] end_request: I/O error, dev sda, sector 255684895
[103051.287687] sd 0:0:0:0: [sda] Unhandled error code
[103051.287691] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.287696] end_request: I/O error, dev sda, sector 255685135
[103051.287834] sd 0:0:0:0: [sda] Unhandled error code
[103051.287838] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.287843] end_request: I/O error, dev sda, sector 255685375
[103051.288022] sd 0:0:0:0: [sda] Unhandled error code
[103051.288025] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.288030] end_request: I/O error, dev sda, sector 255685615
[103051.288160] sd 0:0:0:0: [sda] Unhandled error code
[103051.288163] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.288168] end_request: I/O error, dev sda, sector 255685855
[103051.288306] sd 0:0:0:0: [sda] Unhandled error code
[103051.288309] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.288314] end_request: I/O error, dev sda, sector 255686095
[103051.288438] sd 0:0:0:0: [sda] Unhandled error code
[103051.288441] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.288446] end_request: I/O error, dev sda, sector 255686335
[103051.288571] sd 0:0:0:0: [sda] Unhandled error code
[103051.288575] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.288580] end_request: I/O error, dev sda, sector 255686575
[103051.288648] sd 0:0:0:0: [sda] Unhandled error code
[103051.288651] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.288656] end_request: I/O error, dev sda, sector 255686615
[103051.288785] sd 0:0:0:0: [sda] Unhandled error code
[103051.288789] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.288794] end_request: I/O error, dev sda, sector 255686855
[103051.288921] sd 0:0:0:0: [sda] Unhandled error code
[103051.288924] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.288930] end_request: I/O error, dev sda, sector 255687095
[103051.289067] sd 0:0:0:0: [sda] Unhandled error code
[103051.289070] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.289075] end_request: I/O error, dev sda, sector 255687335
[103051.289216] sd 0:0:0:0: [sda] Unhandled error code
[103051.289220] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.289225] end_request: I/O error, dev sda, sector 255687575
[103051.289407] sd 0:0:0:0: [sda] Unhandled error code
[103051.289410] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.289415] end_request: I/O error, dev sda, sector 255687815
[103051.289545] sd 0:0:0:0: [sda] Unhandled error code
[103051.289548] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.289553] end_request: I/O error, dev sda, sector 255688055
[103051.289682] sd 0:0:0:0: [sda] Unhandled error code
[103051.289686] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.289691] end_request: I/O error, dev sda, sector 255688295
[103051.289842] sd 0:0:0:0: [sda] Unhandled error code
[103051.289845] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.289850] end_request: I/O error, dev sda, sector 255688535
[103051.289980] sd 0:0:0:0: [sda] Unhandled error code
[103051.289983] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.289988] end_request: I/O error, dev sda, sector 255688775
[103051.290111] sd 0:0:0:0: [sda] Unhandled error code
[103051.290114] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.290119] end_request: I/O error, dev sda, sector 255689015
[103051.290256] sd 0:0:0:0: [sda] Unhandled error code
[103051.290260] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.290265] end_request: I/O error, dev sda, sector 255689255
[103051.290402] sd 0:0:0:0: [sda] Unhandled error code
[103051.290406] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.290411] end_request: I/O error, dev sda, sector 255689495
[103051.290553] sd 0:0:0:0: [sda] Unhandled error code
[103051.290556] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.290561] end_request: I/O error, dev sda, sector 255689735
[103051.290700] sd 0:0:0:0: [sda] Unhandled error code
[103051.290703] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.290708] end_request: I/O error, dev sda, sector 255689975
[103051.290844] sd 0:0:0:0: [sda] Unhandled error code
[103051.290847] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.290852] end_request: I/O error, dev sda, sector 255690215
[103051.290974] sd 0:0:0:0: [sda] Unhandled error code
[103051.290978] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.290983] end_request: I/O error, dev sda, sector 255690455
[103051.291125] sd 0:0:0:0: [sda] Unhandled error code
[103051.291128] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.291133] end_request: I/O error, dev sda, sector 255690695
[103051.291267] sd 0:0:0:0: [sda] Unhandled error code
[103051.291270] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.291275] end_request: I/O error, dev sda, sector 255690935
[103051.291420] sd 0:0:0:0: [sda] Unhandled error code
[103051.291424] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.291429] end_request: I/O error, dev sda, sector 255691175
[103051.291560] sd 0:0:0:0: [sda] Unhandled error code
[103051.291564] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.291569] end_request: I/O error, dev sda, sector 255691415
[103051.291698] sd 0:0:0:0: [sda] Unhandled error code
[103051.291701] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.291706] end_request: I/O error, dev sda, sector 255691655
[103051.291849] sd 0:0:0:0: [sda] Unhandled error code
[103051.291852] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.291857] end_request: I/O error, dev sda, sector 255691895
[103051.292008] sd 0:0:0:0: [sda] Unhandled error code
[103051.292011] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.292017] end_request: I/O error, dev sda, sector 255692135
[103051.292227] sd 0:0:0:0: [sda] Unhandled error code
[103051.292230] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.292235] end_request: I/O error, dev sda, sector 255692375
[103051.292396] sd 0:0:0:0: [sda] Unhandled error code
[103051.292399] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.292404] end_request: I/O error, dev sda, sector 255692615
[103051.292508] hub 1-6:1.0: state 7 ports 4 chg 0002 evt 0000
[103051.292643] sd 0:0:0:0: [sda] Unhandled error code
[103051.292647] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.292652] end_request: I/O error, dev sda, sector 255692855
[103051.292828] sd 0:0:0:0: [sda] Unhandled error code
[103051.292831] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.292836] end_request: I/O error, dev sda, sector 255693095
[103051.292977] sd 0:0:0:0: [sda] Unhandled error code
[103051.292980] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.292985] end_request: I/O error, dev sda, sector 255693335
[103051.293133] sd 0:0:0:0: [sda] Unhandled error code
[103051.293136] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.293141] end_request: I/O error, dev sda, sector 255693575
[103051.293272] sd 0:0:0:0: [sda] Unhandled error code
[103051.293275] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.293280] end_request: I/O error, dev sda, sector 255693815
[103051.293416] sd 0:0:0:0: [sda] Unhandled error code
[103051.293420] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.293425] end_request: I/O error, dev sda, sector 255694055
[103051.293487] sd 0:0:0:0: [sda] Unhandled error code
[103051.293491] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.293496] end_request: I/O error, dev sda, sector 258511
[103051.293549] sd 0:0:0:0: [sda] Unhandled error code
[103051.293553] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.293558] end_request: I/O error, dev sda, sector 258535
[103051.293622] sd 0:0:0:0: [sda] Unhandled error code
[103051.293626] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.293631] end_request: I/O error, dev sda, sector 255328319
[103051.293685] sd 0:0:0:0: [sda] Unhandled error code
[103051.293688] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.293693] end_request: I/O error, dev sda, sector 255574439
[103051.293745] sd 0:0:0:0: [sda] Unhandled error code
[103051.293748] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.293753] end_request: I/O error, dev sda, sector 255582639
[103051.293805] sd 0:0:0:0: [sda] Unhandled error code
[103051.293809] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.293814] end_request: I/O error, dev sda, sector 255596407
[103051.293894] sd 0:0:0:0: [sda] Unhandled error code
[103051.293898] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.293903] end_request: I/O error, dev sda, sector 255604607
[103051.293955] sd 0:0:0:0: [sda] Unhandled error code
[103051.293959] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.293964] end_request: I/O error, dev sda, sector 255612807
[103051.294023] sd 0:0:0:0: [sda] Unhandled error code
[103051.294026] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.294031] end_request: I/O error, dev sda, sector 255621007
[103051.294078] sd 0:0:0:0: [sda] Unhandled error code
[103051.294081] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.294086] end_request: I/O error, dev sda, sector 255629207
[103051.294186] Aborting journal on device sda1.
[103051.294261] sd 0:0:0:0: [sda] Unhandled error code
[103051.294265] sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
[103051.294271] end_request: I/O error, dev sda, sector 12423
[103051.295042] hub 1-6:1.0: port 1, status 0100, change 0001, 12 Mb/s
[103051.295412] usb 1-6.1: USB disconnect, address 3
[103051.295416] usb 1-6.1: unregistering device
[103051.295420] usb 1-6.1: usb_disable_device nuking all URBs
[103051.295431] usb 1-6.1: unregistering interface 1-6.1:1.0
[103051.299398] __journal_remove_journal_head: freeing b_committed_data
[103051.300502] usb 1-6.1:1.0: uevent
[103051.300743] usb 1-6.1: uevent
[103051.313245] ext3_abort called.
[103051.313255] EXT3-fs error (device sda1): ext3_journal_start_sb: Detected aborted journal
[103051.313261] Remounting filesystem read-only
[103051.379354] EXT3-fs error (device sda1): ext3_find_entry: reading directory #6979648 offset 0
[103051.379906] EXT3-fs error (device sda1): ext3_find_entry: reading directory #6979648 offset 0
[103051.380099] EXT3-fs error (device sda1): ext3_find_entry: reading directory #6979648 offset 0
[103051.380237] EXT3-fs error (device sda1): ext3_find_entry: reading directory #6979648 offset 0
[103051.396411] EXT3-fs error (device sda1): ext3_find_entry: reading directory #6979636 offset 0
[103051.406406] hub 1-6:1.0: debounce: port 1: total 100ms stable 100ms status 0x100
[103053.704026] hub 1-6:1.0: hub_suspend
[103053.704041] usb 1-6: unlink qh256-0001/ffff88007c53f140 start 255 [1/0 us]
[103053.704360] usb 1-6: usb auto-suspend
[103056.704303] hub 1-0:1.0: hub_suspend
[103056.704319] usb usb1: bus auto-suspend
[103056.704324] ehci_hcd 0000:00:1d.7: suspend root hub
[103083.606368] ext3_abort called.
[103083.606377] EXT3-fs error (device sda1): ext3_put_super: Couldn't clean up the journal

Re: [2.6.30-rc2] usb reset during big file transfer and ext3 error

[Robert Hancock]

(ccing linux-usb)

Rogério Brito wrote:
> Hi there.
> 
> I have an amd64 system running Debian's sid distribution and I installed
> Linux 2.6.30-rc2 on it, as a way to get improvements for the i915
> subsystem.
> 
> Unfortunately, when I was transferring the contents of 2 DVDs from the
> main IDE HD to a USB external HD, I got errors from the USB host, the
> writes on the external HD become failures and the ext3 filesystem there
> enters into error mode, going read-only.
> 
> I eventually lose the access to the device (i.e., the /dev/sd??? device
> isn't there anymore) and I then have to re-run fsck on the given
> filesystem.
> 
> This has already happened 2 or 3 times already and I observed that it
> only occurs when there is high traffic---if I am, say, compiling the
> kernel on that external HD, I don't see any problems.
> 
> Attached is part of the dmesg log that shows the problem. I put the
> whole dmesg at <http://rb.doesntexist.org/linux/>.
> 
> As always, if any further information is needed, please let me know.

You're seeing these:

[103051.265045] ehci_hcd 0000:00:1d.7: detected XactErr len 1536/4096 
retry 1
[103051.265156] ehci_hcd 0000:00:1d.7: detected XactErr len 1536/4096 
retry 2
[103051.265281] ehci_hcd 0000:00:1d.7: detected XactErr len 1536/4096 
retry 3
[103051.265406] ehci_hcd 0000:00:1d.7: detected XactErr len 1536/4096 
retry 4

According to the EHCI spec, XactErr is "Set to a one by the Host 
Controller during status update in the case where the host did not 
receive a valid response from the device (Timeout, CRC, Bad PID, etc.)"

Quite likely this is some kind of hardware problem - maybe the USB port 
doesn't quite provide enough power for the drive, etc. A lot of these 
USB enclosure devices are also rather poor quality in general..

Re: [2.6.30-rc2] usb reset during big file transfer and ext3 error

[Rogério Brito]

Hi, Robert.

On Apr 21 2009, Robert Hancock wrote:
> (ccing linux-usb)

Ok.

> Rogério Brito wrote:
(...)
>> Unfortunately, when I was transferring the contents of 2 DVDs from the
>> main IDE HD to a USB external HD, I got errors from the USB host, the
>> writes on the external HD become failures and the ext3 filesystem there
>> enters into error mode, going read-only.
>>
>> I eventually lose the access to the device (i.e., the /dev/sd??? device
>> isn't there anymore) and I then have to re-run fsck on the given
>> filesystem.
>>
>> This has already happened 2 or 3 times already and I observed that it
>> only occurs when there is high traffic---if I am, say, compiling the
>> kernel on that external HD, I don't see any problems.

I just saw it reoccur once more, this time inducing a stacktrace related
to ext3. :-(

>> Attached is part of the dmesg log that shows the problem. I put the
>> whole dmesg at <http://rb.doesntexist.org/linux/>.
>>
>> As always, if any further information is needed, please let me know.
>
> You're seeing these:
>
> [103051.265045] ehci_hcd 0000:00:1d.7: detected XactErr len 1536/4096  
> retry 1
> [103051.265156] ehci_hcd 0000:00:1d.7: detected XactErr len 1536/4096  
> retry 2
> [103051.265281] ehci_hcd 0000:00:1d.7: detected XactErr len 1536/4096  
> retry 3
> [103051.265406] ehci_hcd 0000:00:1d.7: detected XactErr len 1536/4096  
> retry 4

Precisely.

> According to the EHCI spec, XactErr is "Set to a one by the Host  
> Controller during status update in the case where the host did not  
> receive a valid response from the device (Timeout, CRC, Bad PID,
> etc.)"

Is there any way of controlling the number of retries in the host
controller? Or, perhaps, of controlling the time between retries so that
the device can shape it up again?

> Quite likely this is some kind of hardware problem - maybe the USB
> port doesn't quite provide enough power for the drive, etc.

I see. The first thing I thought about when I saw this comment of yours
was that there could be some heat issue and the drive not cooling
down.

In this particular case, the USB enclosure is externally powered and it
conatins a SATA drive. I also had never seen it occour before when
connected to an EHCI port on another system, even while transferring
more data.

> A lot of these USB enclosure devices are also rather poor quality in
> general..

Agreed. Not everybody does things correctly by the book. OTOH, these are
the devices present in "the real world". Would there be workarounds for
such situations?


Thanks, Rogério Brito.

-- 
Rogério Brito : rbrito@{mackenzie,ime.usp}.br : GPG key 1024D/7C2CAEB8
http://www.ime.usp.br/~rbrito : http://meusite.mackenzie.com.br/rbrito
Projects: algorithms.berlios.de : lame.sf.net : vrms.alioth.debian.org

Re: [2.6.30-rc2] usb reset during big file transfer and ext3 error

[Alan Stern]

On Wed, 22 Apr 2009, [utf-8] Rogério Brito wrote:

> > According to the EHCI spec, XactErr is "Set to a one by the Host  
> > Controller during status update in the case where the host did not  
> > receive a valid response from the device (Timeout, CRC, Bad PID,
> > etc.)"
> 
> Is there any way of controlling the number of retries in the host
> controller? Or, perhaps, of controlling the time between retries so that
> the device can shape it up again?

It's not all that simple.  The host controller allows the OS to set the
number of hardware retries to 1, 2, 3, or unlimited.  Linux uses 3;  
those XactErr debugging messages in your log show that the driver was
extending the number of retries in software.

It's not possible to change the time interval between retries done by
the hardware.  While it is possible in theory to change the interval
between retries done by the driver, it would be rather difficult and
so ehci-hcd doesn't attempt it.

The software retries were introduced to solve one particular problem:  
Many EHCI controllers will generate a transaction error if a data
transfer is occurring on one port at the same time as a device is being
unplugged on another port.  This is clearly a hardware bug, and the
software retries were intended to work around it.  In practice only a
couple of software retries are needed; if the transfer hasn't succeeded
by that point then it's never going to succeed.  I set the upper limit
to 32 retries just to be conservative.

Delaying longer in order to allow the device to shape itself up is
generally hopeless.  I've haven't seen more than one or two cases where
that would work -- and it's quite possible that those cases would have
worked out okay if the software retry mechanism had existed back when
they occurred.  If transaction errors aren't caused by noise in the
cable then they are almost always caused by bugs or failures in the
device.  Once a device's firmware has crashed, it doesn't magically fix
itself.

Alan Stern

Re: [2.6.30-rc2] usb reset during big file transfer and ext3 error

[Rogério Brito]

Hi, Alan.

Sorry for the late reply, but I had some problems with an HD of mine
giving me trouble. :-( Of course, I have backups. :-)

On Apr 22 2009, Alan Stern wrote:
> On Wed, 22 Apr 2009, Rogério Brito wrote:
> > Is there any way of controlling the number of retries in the host
> > controller? Or, perhaps, of controlling the time between retries so
> > that the device can shape it up again?
> 
> It's not all that simple.  The host controller allows the OS to set the
> number of hardware retries to 1, 2, 3, or unlimited.  Linux uses 3;  
> those XactErr debugging messages in your log show that the driver was
> extending the number of retries in software.

Right. I didn't know that. Obviously, setting it to unlimited can give
undefined behavior of the computer.

> It's not possible to change the time interval between retries done by
> the hardware.  While it is possible in theory to change the interval
> between retries done by the driver, it would be rather difficult and
> so ehci-hcd doesn't attempt it.

Oh, what a pity. It seems that the device at hand sort of gets in shape
again after some time, since I have an automounter here and the device
nodes appear again under dev and it auto-mounts the device at the
appropriate mount point. Weird.

> The software retries were introduced to solve one particular problem:
> Many EHCI controllers will generate a transaction error if a data
> transfer is occurring on one port at the same time as a device is
> being unplugged on another port.

Right. I just got myself a (non powered) USB hub and I noticed one thing
(unrelated to this problem): if I plug a USB disk to this hub and, then,
plug a printer, very weird things happen, like the disc being unmounted
or things like that.

I can give you precise details of what happens here, if you're
interested.

OTOH, I think that I may be seeing some other problems with a pen drive
being connected to a port of this machine I'm typing this message on. I
will try to compile a newer kernel, now that -rc4 is released and I
would appreciate if you could help me with the issues that I'm seeing.

> This is clearly a hardware bug, and the software retries were intended
> to work around it.  In practice only a couple of software retries are
> needed; if the transfer hasn't succeeded by that point then it's never
> going to succeed.  I set the upper limit to 32 retries just to be
> conservative.

OK. Thanks for the nice and clear explanation of the problem. I only
wonder why I not seeing these errors on other machines while I *do* see
them on other machines (this one is an intel ICH5).

> If transaction errors aren't caused by noise in the cable then they
> are almost always caused by bugs or failures in the device.

I will try again with a shorter and newer cable. Let's see how that
works. BTW, is there any way to check the quality of a cable? I have a
multimeter here and I would be willing to do some extensive tests.
Testing the USB enclosure is also pretty feasible.

> Once a device's firmware has crashed, it doesn't magically fix itself.

Oh, what a pity that it doesn't recovers itself with a watchdog-like
mechanism.


Thanks for all your help, Rogério.

-- 
Rogério Brito : rbrito@{mackenzie,ime.usp}.br : GPG key 1024D/7C2CAEB8
http://www.ime.usp.br/~rbrito : http://meusite.mackenzie.com.br/rbrito
Projects: algorithms.berlios.de : lame.sf.net : vrms.alioth.debian.org

Re: [2.6.30-rc2] usb reset during big file transfer and ext3 error

[Alan Stern]

On Fri, 1 May 2009, [utf-8] Rogério Brito wrote:

> > It's not all that simple.  The host controller allows the OS to set the
> > number of hardware retries to 1, 2, 3, or unlimited.  Linux uses 3;  
> > those XactErr debugging messages in your log show that the driver was
> > extending the number of retries in software.
> 
> Right. I didn't know that. Obviously, setting it to unlimited can give
> undefined behavior of the computer.

No, the behavior would be defined.  But it wouldn't be what we want.  
Instead of getting an immediate error followed by a reset, you would 
have to wait for the command to time out (somewhere between 10 and 30 
seconds) before the reset occurred.

> > It's not possible to change the time interval between retries done by
> > the hardware.  While it is possible in theory to change the interval
> > between retries done by the driver, it would be rather difficult and
> > so ehci-hcd doesn't attempt it.
> 
> Oh, what a pity. It seems that the device at hand sort of gets in shape
> again after some time, since I have an automounter here and the device
> nodes appear again under dev and it auto-mounts the device at the
> appropriate mount point. Weird.

There is probably a reset in between.  I doubt that the device recovers 
all by itself.

> > The software retries were introduced to solve one particular problem:
> > Many EHCI controllers will generate a transaction error if a data
> > transfer is occurring on one port at the same time as a device is
> > being unplugged on another port.
> 
> Right. I just got myself a (non powered) USB hub and I noticed one thing
> (unrelated to this problem): if I plug a USB disk to this hub and, then,
> plug a printer, very weird things happen, like the disc being unmounted
> or things like that.

That is different from what I was talking about.  The Intel controllers 
in question work okay when a new device is plugged in, but they get 
errors when a device is unplugged.

> > This is clearly a hardware bug, and the software retries were intended
> > to work around it.  In practice only a couple of software retries are
> > needed; if the transfer hasn't succeeded by that point then it's never
> > going to succeed.  I set the upper limit to 32 retries just to be
> > conservative.
> 
> OK. Thanks for the nice and clear explanation of the problem. I only
> wonder why I not seeing these errors on other machines while I *do* see
> them on other machines (this one is an intel ICH5).

Quality varies a lot with USB components, and sometimes you can't tell 
where the problem is.

I've got a USB disk drive and cable that do not work on my home PC, 
although they do work on my office PC.  If I use a different cable then 
the drive does work on the home PC.  If I use the same cable but 
substitute a USB stick for the drive, again it works.  So which 
component is bad: the home PC, the cable, or the drive?

> > If transaction errors aren't caused by noise in the cable then they
> > are almost always caused by bugs or failures in the device.
> 
> I will try again with a shorter and newer cable. Let's see how that
> works. BTW, is there any way to check the quality of a cable? I have a
> multimeter here and I would be willing to do some extensive tests.
> Testing the USB enclosure is also pretty feasible.

I don't know any way to test these things without using some pretty
fancy equipment.

Alan Stern

Re: [2.6.30-rc2] usb reset during big file transfer and ext3 error

[Rogério Brito]

Hi, Alan & Co.

On May 01 2009, Alan Stern wrote:
> I've got a USB disk drive and cable that do not work on my home PC, 
> although they do work on my office PC.  If I use a different cable then 
> the drive does work on the home PC.  If I use the same cable but 
> substitute a USB stick for the drive, again it works.  So which 
> component is bad: the home PC, the cable, or the drive?

Yes, right.

Resuming our earlier discussion, I got another case of weird USB
messages here with kernel 2.6.30-rc5 (sorry, I have not yet had time to
use anything newer).

My father has a USB (1.1, I would say, which matches what the logs say)
stick/pen drive that, when I connect to my ECHI controller on my machine
with an ICH5 chipset, I get:

- - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
[ 2285.628018] usb 4-2: new full speed USB device using uhci_hcd and address 2
[ 2285.784924] usb 4-2: New USB device found, idVendor=067b, idProduct=2315
[ 2285.784932] usb 4-2: New USB device strings: Mfr=1, Product=3, SerialNumber=0
[ 2285.784936] usb 4-2: Product: USB Embedded Hub
[ 2285.784939] usb 4-2: Manufacturer: Leading Driver Co.,LTD.
[ 2285.785039] PM: Adding info for usb:4-2
[ 2285.785084] usb 4-2: configuration #1 chosen from 1 choice
[ 2285.787985] PM: Adding info for usb:4-2:1.0
[ 2285.788046] hub 4-2:1.0: USB hub found
[ 2285.789956] hub 4-2:1.0: 2 ports detected
[ 2285.794051] PM: Adding info for No Bus:usbdev4.2_ep81
[ 2285.794137] PM: Adding info for No Bus:usbdev4.2_ep00
[ 2286.064854] usb 4-2.1: new full speed USB device using uhci_hcd and address 3
[ 2286.184819] usb 4-2.1: New USB device found, idVendor=067b, idProduct=2317
[ 2286.184825] usb 4-2.1: New USB device strings: Mfr=1, Product=4, SerialNumber=0
[ 2286.184830] usb 4-2.1: Product: USB Mass Storage Device
[ 2286.184833] usb 4-2.1: Manufacturer: Leading Driver Co.,LTD.
[ 2286.184926] PM: Adding info for usb:4-2.1
[ 2286.184974] usb 4-2.1: configuration #1 chosen from 1 choice
[ 2286.187878] PM: Adding info for usb:4-2.1:1.0
[ 2286.187994] PM: Adding info for No Bus:usbdev4.3_ep01
[ 2286.188068] PM: Adding info for No Bus:usbdev4.3_ep82
[ 2286.188133] PM: Adding info for No Bus:usbdev4.3_ep00
[ 2286.239239] SCSI subsystem initialized
[ 2286.253935] Initializing USB Mass Storage driver...
[ 2286.254816] usb 4-2.2: new full speed USB device using uhci_hcd and address 4
[ 2286.255696] scsi0 : SCSI emulation for USB Mass Storage devices
[ 2286.255763] PM: Adding info for scsi:host0
[ 2286.255830] PM: Adding info for No Bus:host0
[ 2286.256419] usbcore: registered new interface driver usb-storage
[ 2286.256426] USB Mass Storage support registered.
[ 2286.257378] usb-storage: device found at 3
[ 2286.257382] usb-storage: waiting for device to settle before scanning
[ 2286.372799] usb 4-2.2: New USB device found, idVendor=067b, idProduct=2316
[ 2286.372807] usb 4-2.2: New USB device strings: Mfr=1, Product=5, SerialNumber=0
[ 2286.372811] usb 4-2.2: Product: USB Security Device
[ 2286.372814] usb 4-2.2: Manufacturer: Leading Driver Co.,LTD.
[ 2286.372906] PM: Adding info for usb:4-2.2
[ 2286.372957] usb 4-2.2: configuration #1 chosen from 1 choice
[ 2286.375825] PM: Adding info for usb:4-2.2:1.0
[ 2286.375951] PM: Adding info for No Bus:usbdev4.4_ep00
[ 2291.258587] usb-storage: device scan complete
[ 2291.261567] scsi 0:0:0:0: Direct-Access     Prolific USB Flash Disk   1.00 PQ: 0 ANSI: 0 CCS
[ 2291.262023] PM: Adding info for scsi:target0:0:0
[ 2291.262497] PM: Adding info for scsi:0:0:0:0
[ 2291.262711] PM: Adding info for No Bus:0:0:0:0
[ 2291.273924] Driver 'sd' needs updating - please use bus_type methods
[ 2291.274557] PM: Adding info for No Bus:0:0:0:0
[ 2291.280525] sd 0:0:0:0: [sda] 256000 512-byte hardware sectors: (131 MB/125 MiB)
[ 2291.283532] sd 0:0:0:0: [sda] Write Protect is off
[ 2291.283539] sd 0:0:0:0: [sda] Mode Sense: 23 00 00 00
[ 2291.283543] sd 0:0:0:0: [sda] Assuming drive cache: write through
[ 2291.283603] PM: Adding info for No Bus:sda
[ 2291.290517] sd 0:0:0:0: ioctl_internal_command return code = 8000002
[ 2291.290523]    : Sense Key : 0x0 [current] 
[ 2291.290529]    : ASC=0x0 ASCQ=0x0
[ 2291.298513] sd 0:0:0:0: [sda] Assuming drive cache: write through
[ 2291.298520]  sda: sda1
[ 2291.304573] PM: Adding info for No Bus:sda1
[ 2291.309522] sd 0:0:0:0: ioctl_internal_command return code = 8000002
[ 2291.309527]    : Sense Key : 0x0 [current] 
[ 2291.309533]    : ASC=0x0 ASCQ=0x0
[ 2291.309625] PM: Adding info for No Bus:8:0
[ 2291.309651] sd 0:0:0:0: [sda] Attached SCSI removable disk
[ 2291.330510] sd 0:0:0:0: ioctl_internal_command return code = 8000002
[ 2291.330518]    : Sense Key : 0x0 [current] 
[ 2291.330524]    : ASC=0x0 ASCQ=0x0
[ 2291.634434] sd 0:0:0:0: ioctl_internal_command return code = 8000002
[ 2291.634440]    : Sense Key : 0x0 [current] 
[ 2291.634446]    : ASC=0x0 ASCQ=0x0
[ 2291.703422] sd 0:0:0:0: ioctl_internal_command return code = 8000002
[ 2291.703430]    : Sense Key : 0x0 [current] 
[ 2291.703436]    : ASC=0x0 ASCQ=0x0
[ 2291.725411] sd 0:0:0:0: ioctl_internal_command return code = 8000002
[ 2291.725415]    : Sense Key : 0x0 [current] 
[ 2291.725420]    : ASC=0x0 ASCQ=0x0
[ 2291.735409] sd 0:0:0:0: ioctl_internal_command return code = 8000002
[ 2291.735417]    : Sense Key : 0x0 [current] 
[ 2291.735423]    : ASC=0x0 ASCQ=0x0
[ 2292.036329] sd 0:0:0:0: ioctl_internal_command return code = 8000002
[ 2292.036336]    : Sense Key : 0x0 [current] 
[ 2292.036342]    : ASC=0x0 ASCQ=0x0
[ 2292.046354] sd 0:0:0:0: ioctl_internal_command return code = 8000002
[ 2292.046361]    : Sense Key : 0x0 [current] 
[ 2292.046367]    : ASC=0x0 ASCQ=0x0
[ 2292.348248] sd 0:0:0:0: ioctl_internal_command return code = 8000002
[ 2292.348255]    : Sense Key : 0x0 [current] 
[ 2292.348261]    : ASC=0x0 ASCQ=0x0
[ 2292.414240] sd 0:0:0:0: ioctl_internal_command return code = 8000002
[ 2292.414246]    : Sense Key : 0x0 [current] 
[ 2292.414252]    : ASC=0x0 ASCQ=0x0
- - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -

In particular, those ioctl_internal_command return code messages seem
strange, regarding other USB devices that I have. Are they being shown
because I have some debugging information in my kernel or are they
abnormal?


Thanks for any help,

-- 
Rogério Brito : rbrito@{mackenzie,ime.usp}.br : GPG key 1024D/7C2CAEB8
http://www.ime.usp.br/~rbrito : http://meusite.mackenzie.com.br/rbrito
Projects: algorithms.berlios.de : lame.sf.net : vrms.alioth.debian.org

Re: [2.6.30-rc2] usb reset during big file transfer and ext3 error

[Alan Stern]

On Sun, 24 May 2009, [utf-8] Rogério Brito wrote:

> Resuming our earlier discussion, I got another case of weird USB
> messages here with kernel 2.6.30-rc5 (sorry, I have not yet had time to
> use anything newer).
> 
> My father has a USB (1.1, I would say, which matches what the logs say)
> stick/pen drive that, when I connect to my ECHI controller on my machine
> with an ICH5 chipset, I get:

> [ 2291.280525] sd 0:0:0:0: [sda] 256000 512-byte hardware sectors: (131 MB/125 MiB)
> [ 2291.283532] sd 0:0:0:0: [sda] Write Protect is off
> [ 2291.283539] sd 0:0:0:0: [sda] Mode Sense: 23 00 00 00
> [ 2291.283543] sd 0:0:0:0: [sda] Assuming drive cache: write through
> [ 2291.283603] PM: Adding info for No Bus:sda
> [ 2291.290517] sd 0:0:0:0: ioctl_internal_command return code = 8000002
> [ 2291.290523]    : Sense Key : 0x0 [current] 
> [ 2291.290529]    : ASC=0x0 ASCQ=0x0
> [ 2291.298513] sd 0:0:0:0: [sda] Assuming drive cache: write through
> [ 2291.298520]  sda: sda1
> [ 2291.304573] PM: Adding info for No Bus:sda1
> [ 2291.309522] sd 0:0:0:0: ioctl_internal_command return code = 8000002
> [ 2291.309527]    : Sense Key : 0x0 [current] 
> [ 2291.309533]    : ASC=0x0 ASCQ=0x0
...

> In particular, those ioctl_internal_command return code messages seem
> strange, regarding other USB devices that I have. Are they being shown
> because I have some debugging information in my kernel or are they
> abnormal?

It is abnormal, but I can't tell what the reason is without more 
information.  You should try using usbmon (see 
Documentation/usb/usbmon.txt) to trace these events.

Alan Stern

ioctl_internal_command messages (was: Re: [2.6.30-rc2] usb reset during big file transfer and ext3 error)

[Rogério Brito]

On May 24 2009, Alan Stern wrote:
> On Sun, 24 May 2009, [utf-8] Rogério Brito wrote:
> > In particular, those ioctl_internal_command return code messages seem
> > strange, regarding other USB devices that I have. Are they being shown
> > because I have some debugging information in my kernel or are they
> > abnormal?
> 
> It is abnormal, but I can't tell what the reason is without more 
> information.  You should try using usbmon (see 
> Documentation/usb/usbmon.txt) to trace these events.

Recompiling my kernel right now with usbmon support. Will send you logs
very soon.


Thanks,

-- 
Rogério Brito : rbrito@{mackenzie,ime.usp}.br : GPG key 1024D/7C2CAEB8
http://www.ime.usp.br/~rbrito : http://meusite.mackenzie.com.br/rbrito
Projects: algorithms.berlios.de : lame.sf.net : vrms.alioth.debian.org

Re: [2.6.30-rc2] usb reset during big file transfer and ext3 error

[Rogério Brito]

[-- Attachment #1: Type: text/plain, Size: 4172 bytes --]

On May 24 2009, Alan Stern wrote:
> It is abnormal, but I can't tell what the reason is without more
> information.  You should try using usbmon (see
> Documentation/usb/usbmon.txt) to trace these events.

Here you go with a log that is pure text (compressed). The part of dmesg
relative to the USB plugging is here:

- - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
[  248.286615] usb-storage: device found at 3
[  248.286620] usb-storage: waiting for device to settle before scanning
[  248.286631] usbcore: registered new interface driver usb-storage
[  248.286636] USB Mass Storage support registered.
[  248.351740] usb 4-2.2: New USB device found, idVendor=067b, idProduct=2316
[  248.351749] usb 4-2.2: New USB device strings: Mfr=1, Product=5, SerialNumber=0
[  248.351753] usb 4-2.2: Product: USB Security Device
[  248.351756] usb 4-2.2: Manufacturer: Leading Driver Co.,LTD.
[  248.351860] PM: Adding info for usb:4-2.2
[  248.351907] usb 4-2.2: configuration #1 chosen from 1 choice
[  248.354759] PM: Adding info for usb:4-2.2:1.0
[  248.354894] PM: Adding info for No Bus:usbdev4.4_ep00
[  253.288125] usb-storage: device scan complete
[  253.291081] scsi 0:0:0:0: Direct-Access     Prolific USB Flash Disk   1.00 PQ: 0 ANSI: 0 CCS
[  253.291476] PM: Adding info for scsi:target0:0:0
[  253.291903] PM: Adding info for scsi:0:0:0:0
[  253.292167] PM: Adding info for No Bus:0:0:0:0
[  253.331140] Driver 'sd' needs updating - please use bus_type methods
[  253.331290] PM: Adding info for No Bus:0:0:0:0
[  253.337069] sd 0:0:0:0: [sda] 256000 512-byte hardware sectors: (131 MB/125 MiB)
[  253.340068] sd 0:0:0:0: [sda] Write Protect is off
[  253.340073] sd 0:0:0:0: [sda] Mode Sense: 23 00 00 00
[  253.340077] sd 0:0:0:0: [sda] Assuming drive cache: write through
[  253.340130] PM: Adding info for No Bus:sda
[  253.347047] sd 0:0:0:0: ioctl_internal_command return code = 8000002
[  253.347053]    : Sense Key : 0x0 [current] 
[  253.347059]    : ASC=0x0 ASCQ=0x0
[  253.355049] sd 0:0:0:0: [sda] Assuming drive cache: write through
[  253.355057]  sda: sda1
[  253.361106] PM: Adding info for No Bus:sda1
[  253.366054] sd 0:0:0:0: ioctl_internal_command return code = 8000002
[  253.366060]    : Sense Key : 0x0 [current] 
[  253.366066]    : ASC=0x0 ASCQ=0x0
[  253.366162] PM: Adding info for No Bus:8:0
[  253.366196] sd 0:0:0:0: [sda] Attached SCSI removable disk
[  253.386056] sd 0:0:0:0: ioctl_internal_command return code = 8000002
[  253.386063]    : Sense Key : 0x0 [current] 
[  253.386069]    : ASC=0x0 ASCQ=0x0
[  253.690947] sd 0:0:0:0: ioctl_internal_command return code = 8000002
[  253.690954]    : Sense Key : 0x0 [current] 
[  253.690960]    : ASC=0x0 ASCQ=0x0
[  253.784900] sd 0:0:0:0: ioctl_internal_command return code = 8000002
[  253.784909]    : Sense Key : 0x0 [current] 
[  253.784916]    : ASC=0x0 ASCQ=0x0
[  253.806909] sd 0:0:0:0: ioctl_internal_command return code = 8000002
[  253.806914]    : Sense Key : 0x0 [current] 
[  253.806919]    : ASC=0x0 ASCQ=0x0
[  253.816898] sd 0:0:0:0: ioctl_internal_command return code = 8000002
[  253.816904]    : Sense Key : 0x0 [current] 
[  253.816910]    : ASC=0x0 ASCQ=0x0
[  254.118799] sd 0:0:0:0: ioctl_internal_command return code = 8000002
[  254.118806]    : Sense Key : 0x0 [current] 
[  254.118812]    : ASC=0x0 ASCQ=0x0
[  254.128798] sd 0:0:0:0: ioctl_internal_command return code = 8000002
[  254.128804]    : Sense Key : 0x0 [current] 
[  254.128810]    : ASC=0x0 ASCQ=0x0
[  254.432691] sd 0:0:0:0: ioctl_internal_command return code = 8000002
[  254.432697]    : Sense Key : 0x0 [current] 
[  254.432703]    : ASC=0x0 ASCQ=0x0
[  254.495644] sd 0:0:0:0: ioctl_internal_command return code = 8000002
[  254.495650]    : Sense Key : 0x0 [current] 
[  254.495656]    : ASC=0x0 ASCQ=0x0
- - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -

If you need further information, please let me know.


Thanks,

-- 
Rogério Brito : rbrito@{mackenzie,ime.usp}.br : GPG key 1024D/7C2CAEB8
http://www.ime.usp.br/~rbrito : http://meusite.mackenzie.com.br/rbrito
Projects: algorithms.berlios.de : lame.sf.net : vrms.alioth.debian.org

[-- Attachment #2: 1.mon.out.bz2 --]
[-- Type: application/octet-stream, Size: 12307 bytes --]

Re: [2.6.30-rc2] usb reset during big file transfer and ext3 error

[Alan Stern]

On Sun, 24 May 2009, [utf-8] Rogério Brito wrote:

> On May 24 2009, Alan Stern wrote:
> > It is abnormal, but I can't tell what the reason is without more
> > information.  You should try using usbmon (see
> > Documentation/usb/usbmon.txt) to trace these events.
> 
> Here you go with a log that is pure text (compressed). The part of dmesg
> relative to the USB plugging is here:
> 
> - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
> [  248.286615] usb-storage: device found at 3
> [  248.286620] usb-storage: waiting for device to settle before scanning
> [  248.286631] usbcore: registered new interface driver usb-storage
> [  248.286636] USB Mass Storage support registered.
> [  248.351740] usb 4-2.2: New USB device found, idVendor=067b, idProduct=2316
> [  248.351749] usb 4-2.2: New USB device strings: Mfr=1, Product=5, SerialNumber=0
> [  248.351753] usb 4-2.2: Product: USB Security Device
> [  248.351756] usb 4-2.2: Manufacturer: Leading Driver Co.,LTD.
> [  248.351860] PM: Adding info for usb:4-2.2
> [  248.351907] usb 4-2.2: configuration #1 chosen from 1 choice
> [  248.354759] PM: Adding info for usb:4-2.2:1.0
> [  248.354894] PM: Adding info for No Bus:usbdev4.4_ep00
> [  253.288125] usb-storage: device scan complete
> [  253.291081] scsi 0:0:0:0: Direct-Access     Prolific USB Flash Disk   1.00 PQ: 0 ANSI: 0 CCS
> [  253.291476] PM: Adding info for scsi:target0:0:0
> [  253.291903] PM: Adding info for scsi:0:0:0:0
> [  253.292167] PM: Adding info for No Bus:0:0:0:0
> [  253.331140] Driver 'sd' needs updating - please use bus_type methods
> [  253.331290] PM: Adding info for No Bus:0:0:0:0
> [  253.337069] sd 0:0:0:0: [sda] 256000 512-byte hardware sectors: (131 MB/125 MiB)
> [  253.340068] sd 0:0:0:0: [sda] Write Protect is off
> [  253.340073] sd 0:0:0:0: [sda] Mode Sense: 23 00 00 00
> [  253.340077] sd 0:0:0:0: [sda] Assuming drive cache: write through
> [  253.340130] PM: Adding info for No Bus:sda
> [  253.347047] sd 0:0:0:0: ioctl_internal_command return code = 8000002
> [  253.347053]    : Sense Key : 0x0 [current] 
> [  253.347059]    : ASC=0x0 ASCQ=0x0

I see the problem.  It's a bug in the Prolific drive.  The drive says
that it has removable media, which is not true.  Then when the computer
tells the drive to lock the media in place, the drive reports an error.  
And it doesn't use the proper error code, so the computer doesn't
know what went wrong.

You can test this by setting a "quirks" option for usb-storage, to tell 
it that the Prolific drive does not understand the "Lock" command:

	modprobe usb-storage quirks=67b:2316:L

or

	echo 67b:2316:L >/sys/module/usb_storage/parameters/quirks

If that eliminates the errors, we can add a permanent quirk entry for 
this device.

Alan Stern

[PATCH] usb-storage: include USB drive in unusual_devs list

[Rogério Brito]

Hi again, Alan.

And thank you very much for your valuable (and always enlightening) comments.

On May 24 2009, Alan Stern wrote:
> I see the problem.  It's a bug in the Prolific drive.  The drive says
> that it has removable media, which is not true.  Then when the computer
> tells the drive to lock the media in place, the drive reports an error.  
> And it doesn't use the proper error code, so the computer doesn't
> know what went wrong.

Hummm, that's bad. :-(

> You can test this by setting a "quirks" option for usb-storage, to tell 
> it that the Prolific drive does not understand the "Lock" command:
> 
> 	modprobe usb-storage quirks=67b:2316:L

Well, I did that, but it, unfortunately, didn't seem to work:

- - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
chagas:~# dmesg | tail -n 45; cat /sys/module/usb_storage/parameters/quirks; lsusb
[ 2703.243277] Driver 'sd' needs updating - please use bus_type methods
[ 2703.243433] PM: Adding info for No Bus:0:0:0:0
[ 2703.249091] sd 0:0:0:0: [sda] 256000 512-byte hardware sectors: (131 MB/125 MiB)
[ 2703.252061] sd 0:0:0:0: [sda] Write Protect is off
[ 2703.252067] sd 0:0:0:0: [sda] Mode Sense: 23 00 00 00
[ 2703.252071] sd 0:0:0:0: [sda] Assuming drive cache: write through
[ 2703.252123] PM: Adding info for No Bus:sda
[ 2703.259056] sd 0:0:0:0: ioctl_internal_command return code = 8000002
[ 2703.259061]    : Sense Key : 0x0 [current] 
[ 2703.259067]    : ASC=0x0 ASCQ=0x0
[ 2703.267025] sd 0:0:0:0: [sda] Assuming drive cache: write through
[ 2703.267032]  sda: sda1
[ 2703.273099] PM: Adding info for No Bus:sda1
[ 2703.278056] sd 0:0:0:0: ioctl_internal_command return code = 8000002
[ 2703.278061]    : Sense Key : 0x0 [current] 
[ 2703.278067]    : ASC=0x0 ASCQ=0x0
[ 2703.278171] PM: Adding info for No Bus:8:0
[ 2703.278195] sd 0:0:0:0: [sda] Attached SCSI removable disk
[ 2703.300019] sd 0:0:0:0: ioctl_internal_command return code = 8000002
[ 2703.300026]    : Sense Key : 0x0 [current] 
[ 2703.300033]    : ASC=0x0 ASCQ=0x0
[ 2703.603961] sd 0:0:0:0: ioctl_internal_command return code = 8000002
[ 2703.603968]    : Sense Key : 0x0 [current] 
[ 2703.603974]    : ASC=0x0 ASCQ=0x0
[ 2703.671981] sd 0:0:0:0: ioctl_internal_command return code = 8000002
[ 2703.671988]    : Sense Key : 0x0 [current] 
[ 2703.671994]    : ASC=0x0 ASCQ=0x0
[ 2703.693975] sd 0:0:0:0: ioctl_internal_command return code = 8000002
[ 2703.693981]    : Sense Key : 0x0 [current] 
[ 2703.693987]    : ASC=0x0 ASCQ=0x0
[ 2703.703974] sd 0:0:0:0: ioctl_internal_command return code = 8000002
[ 2703.703981]    : Sense Key : 0x0 [current] 
[ 2703.703987]    : ASC=0x0 ASCQ=0x0
[ 2704.006895] sd 0:0:0:0: ioctl_internal_command return code = 8000002
[ 2704.006902]    : Sense Key : 0x0 [current] 
[ 2704.006908]    : ASC=0x0 ASCQ=0x0
[ 2704.016920] sd 0:0:0:0: ioctl_internal_command return code = 8000002
[ 2704.016927]    : Sense Key : 0x0 [current] 
[ 2704.016933]    : ASC=0x0 ASCQ=0x0
[ 2704.318865] sd 0:0:0:0: ioctl_internal_command return code = 8000002
[ 2704.318871]    : Sense Key : 0x0 [current] 
[ 2704.318878]    : ASC=0x0 ASCQ=0x0
[ 2704.366850] sd 0:0:0:0: ioctl_internal_command return code = 8000002
[ 2704.366857]    : Sense Key : 0x0 [current] 
[ 2704.366863]    : ASC=0x0 ASCQ=0x0
67b:2316:L
Bus 003 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 002 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 004 Device 004: ID 067b:2316 Prolific Technology, Inc. Flash Disk Security Device
Bus 004 Device 003: ID 067b:2317 Prolific Technology, Inc. Mass Storage Device
Bus 004 Device 002: ID 067b:2315 Prolific Technology, Inc. Flash Disk Embedded Hub
Bus 004 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
chagas:~#
- - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -

> If that eliminates the errors, we can add a permanent quirk entry for 
> this device.

I can test whatever you want me to, so that this can be fixed. The above
lsusb log shows that, perhaps, the quirks option should be set for the
device 067b:2317, instead of 067b:2316, as you told me to?

(I'm going to verify it right now).

Yes, that works. Using 67b:2317:L as a quirk eliminates the messages.
And I do get the

[ 3454.054150] usb-storage 4-2.1:1.0: Quirks match for vid 067b pid 2317: 80

message. Therefore, a proposal:

This patch adds a quirk entry for the Leading Driver UD-11
usb flash drive.

As Alan Stern told me, the device doesn't deal correctly with
the locking media feature of the device, and this patch
incorporates it.

Compiled, tested, working.


Signed-off-by: Rogério Brito <rbrito@ime.usp.br>

---

The US_PR_DEVICE macro could be changed to US_PR_CBI, from what
I saw in the udevadm info tree.

--- a/drivers/usb/storage/unusual_devs.h
+++ b/drivers/usb/storage/unusual_devs.h
@@ -838,6 +838,19 @@ UNUSUAL_DEV( 0x066f, 0x8000, 0x0001, 0x0
 		US_SC_DEVICE, US_PR_DEVICE, NULL,
 		US_FL_FIX_CAPACITY ),
 
+/* Reported by Rogério Brito <rbrito@ime.usp.br> */
+/* 'lsusb' tells:
+ *    "Prolific Technology, Inc. Mass Storage Device"
+ * but 'udevadm info' says:
+ *    ATTR{manufacturer}=="Leading Driver Co.,LTD."
+ *    ATTR{product}=="USB Mass Storage Device"
+ */
+UNUSUAL_DEV( 0x067b, 0x2317, 0x0001, 0x001,
+		"Prolific Technology, Inc.",
+		"Mass Storage Device",
+		US_SC_DEVICE, US_PR_DEVICE, NULL,
+		US_FL_NOT_LOCKABLE ),
+
 /* Reported by Richard -=[]=- <micro_flyer@hotmail.com> */
 /* Change to bcdDeviceMin (0x0100 to 0x0001) reported by
  * Thomas Bartosik <tbartdev@gmx-topmail.de> */


Actually, I just ventured myself and created a patch, attached (sorry, I
know that people don't like attached patches, but I don't want to mix


Thank you so much as always, Rogério Brito.

-- 
Rogério Brito : rbrito@{mackenzie,ime.usp}.br : GPG key 1024D/7C2CAEB8
http://www.ime.usp.br/~rbrito : http://meusite.mackenzie.com.br/rbrito
Projects: algorithms.berlios.de : lame.sf.net : vrms.alioth.debian.org

Re: [PATCH] usb-storage: include USB drive in unusual_devs list

[Alan Stern]

On Mon, 25 May 2009, [utf-8] Rogério Brito wrote:

> 67b:2316:L
> Bus 003 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 002 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
> Bus 004 Device 004: ID 067b:2316 Prolific Technology, Inc. Flash Disk Security Device
> Bus 004 Device 003: ID 067b:2317 Prolific Technology, Inc. Mass Storage Device
> Bus 004 Device 002: ID 067b:2315 Prolific Technology, Inc. Flash Disk Embedded Hub
> Bus 004 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
> Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
> chagas:~#
> - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
> 
> > If that eliminates the errors, we can add a permanent quirk entry for 
> > this device.
> 
> I can test whatever you want me to, so that this can be fixed. The above
> lsusb log shows that, perhaps, the quirks option should be set for the
> device 067b:2317, instead of 067b:2316, as you told me to?

Yes, my fault, I mixed up the two device IDs.

> (I'm going to verify it right now).
> 
> Yes, that works. Using 67b:2317:L as a quirk eliminates the messages.
> And I do get the
> 
> [ 3454.054150] usb-storage 4-2.1:1.0: Quirks match for vid 067b pid 2317: 80
> 
> message. Therefore, a proposal:
> 
> This patch adds a quirk entry for the Leading Driver UD-11
> usb flash drive.
> 
> As Alan Stern told me, the device doesn't deal correctly with
> the locking media feature of the device, and this patch
> incorporates it.
> 
> Compiled, tested, working.
> 
> 
> Signed-off-by: Rogério Brito <rbrito@ime.usp.br>
> 
> ---
> 
> The US_PR_DEVICE macro could be changed to US_PR_CBI, from what
> I saw in the udevadm info tree.
> 
> --- a/drivers/usb/storage/unusual_devs.h
> +++ b/drivers/usb/storage/unusual_devs.h
> @@ -838,6 +838,19 @@ UNUSUAL_DEV( 0x066f, 0x8000, 0x0001, 0x0
>  		US_SC_DEVICE, US_PR_DEVICE, NULL,
>  		US_FL_FIX_CAPACITY ),
>  
> +/* Reported by Rogério Brito <rbrito@ime.usp.br> */

I think you're not supposed to use non-ASCII characters in comments, 
although they're okay in the Changelog.

> +/* 'lsusb' tells:
> + *    "Prolific Technology, Inc. Mass Storage Device"
> + * but 'udevadm info' says:
> + *    ATTR{manufacturer}=="Leading Driver Co.,LTD."
> + *    ATTR{product}=="USB Mass Storage Device"

Don't worry about these attributes.  Leave just the Prolific name.

> + */
> +UNUSUAL_DEV( 0x067b, 0x2317, 0x0001, 0x001,
> +		"Prolific Technology, Inc.",
> +		"Mass Storage Device",
> +		US_SC_DEVICE, US_PR_DEVICE, NULL,
> +		US_FL_NOT_LOCKABLE ),
> +
>  /* Reported by Richard -=[]=- <micro_flyer@hotmail.com> */
>  /* Change to bcdDeviceMin (0x0100 to 0x0001) reported by
>   * Thomas Bartosik <tbartdev@gmx-topmail.de> */
> 
> 
> Actually, I just ventured myself and created a patch, attached (sorry, I
> know that people don't like attached patches, but I don't want to mix

This looks good.  Make those suggested changes and submit it to Phil 
Dibowitz <phil@ipom.com>; it might even get merged in time to appear 
in 2.6.30.

Alan Stern

[PATCH] usb-storage: include USB drive in unusual_devs list

[Rogério Brito]

On May 25 2009, Alan Stern wrote:
> This looks good.  Make those suggested changes and submit it to Phil 
> Dibowitz <phil@ipom.com>; it might even get merged in time to appear 
> in 2.6.30.

Thanks, Alan. Here it goes:

This patch adds a quirk entry for the Leading Driver UD-11 usb flash
drive.

As Alan Stern told me, the device doesn't deal correctly with the
locking media feature of the device, and this patch incorporates it.

Compiled, tested, working.


Signed-off-by: Rogério Brito <rbrito@ime.usp.br>

---

--- a/drivers/usb/storage/unusual_devs.h
+++ b/drivers/usb/storage/unusual_devs.h
@@ -838,6 +838,13 @@ UNUSUAL_DEV( 0x066f, 0x8000, 0x0001, 0x0
 		US_SC_DEVICE, US_PR_DEVICE, NULL,
 		US_FL_FIX_CAPACITY ),
 
+/* Reported by Rogerio Brito <rbrito@ime.usp.br> */
+UNUSUAL_DEV( 0x067b, 0x2317, 0x0001, 0x001,
+		"Prolific Technology, Inc.",
+		"Mass Storage Device",
+		US_SC_DEVICE, US_PR_DEVICE, NULL,
+		US_FL_NOT_LOCKABLE ),
+
 /* Reported by Richard -=[]=- <micro_flyer@hotmail.com> */
 /* Change to bcdDeviceMin (0x0100 to 0x0001) reported by
  * Thomas Bartosik <tbartdev@gmx-topmail.de> */

-- 
Rogério Brito : rbrito@{mackenzie,ime.usp}.br : GPG key 1024D/7C2CAEB8
http://www.ime.usp.br/~rbrito : http://meusite.mackenzie.com.br/rbrito
Projects: algorithms.berlios.de : lame.sf.net : vrms.alioth.debian.org

[PATCH] usb-storage: include USB drive in unusual_devs list

[Rogério Brito]

On May 25 2009, Alan Stern wrote:
> This looks good.  Make those suggested changes and submit it to Phil 
> Dibowitz <phil@ipom.com>; it might even get merged in time to appear 
> in 2.6.30.

Thanks, Alan. Here it goes:

This patch adds a quirk entry for the Leading Driver UD-11 usb flash
drive.

As Alan Stern told me, the device doesn't deal correctly with the
locking media feature of the device, and this patch incorporates it.

Compiled, tested, working.


Signed-off-by: Rogério Brito <rbrito@ime.usp.br>

---

It seems that his patch was missed in the previous release. I'm just
returning and seeing which patches were missed.

Please, apply.

--- a/drivers/usb/storage/unusual_devs.h
+++ b/drivers/usb/storage/unusual_devs.h
@@ -838,6 +838,13 @@ UNUSUAL_DEV( 0x066f, 0x8000, 0x0001, 0x0
 		US_SC_DEVICE, US_PR_DEVICE, NULL,
 		US_FL_FIX_CAPACITY ),
 
+/* Reported by Rogerio Brito <rbrito@ime.usp.br> */
+UNUSUAL_DEV( 0x067b, 0x2317, 0x0001, 0x001,
+		"Prolific Technology, Inc.",
+		"Mass Storage Device",
+		US_SC_DEVICE, US_PR_DEVICE, NULL,
+		US_FL_NOT_LOCKABLE ),
+
 /* Reported by Richard -=[]=- <micro_flyer@hotmail.com> */
 /* Change to bcdDeviceMin (0x0100 to 0x0001) reported by
  * Thomas Bartosik <tbartdev@gmx-topmail.de> */

-- 
Rogério Brito : rbrito@{mackenzie,ime.usp}.br : GPG key 1024D/7C2CAEB8
http://www.ime.usp.br/~rbrito : http://meusite.mackenzie.com.br/rbrito
Projects: algorithms.berlios.de : lame.sf.net : vrms.alioth.debian.org

-- 
Rogério Brito : rbrito@{mackenzie,ime.usp}.br : GPG key 1024D/7C2CAEB8
http://www.ime.usp.br/~rbrito : http://meusite.mackenzie.com.br/rbrito
Projects: algorithms.berlios.de : lame.sf.net : vrms.alioth.debian.org