usb_storage stuck on an I/O error

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



Hi guys!
I have a μSD card that 100%-reproducibly causes the following when tested
with f3probe:

[ 9241.126155] usb 2-1: new high-speed USB device number 3 using ehci-pci
[ 9241.287011] usb 2-1: New USB device found, idVendor=1976, idProduct=4082
[ 9241.293846] usb 2-1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 9241.301121] usb 2-1: Product: USB Reader
[ 9241.305146] usb 2-1: Manufacturer: ChipsBnk
[ 9241.309429] usb 2-1: SerialNumber: 110074973765
[ 9241.327255] usb-storage 2-1:1.0: USB Mass Storage device detected
[ 9241.333801] scsi host8: usb-storage 2-1:1.0
[ 9241.338194] usbcore: registered new interface driver usb-storage
[ 9242.370935] scsi 8:0:0:0: Direct-Access     ChipsBnk   Multi-Reader   4082 PQ: 0 ANSI: 2
[ 9242.379943] sd 8:0:0:0: Attached scsi generic sg2 type 0
[ 9242.381523] sd 8:0:0:0: [sdc] 30679040 512-byte logical blocks: (15.7 GB/14.6 GiB)
[ 9242.382135] sd 8:0:0:0: [sdc] Write Protect is off
[ 9242.382137] sd 8:0:0:0: [sdc] Mode Sense: 0b 00 00 08
[ 9242.382755] sd 8:0:0:0: [sdc] No Caching mode page found
[ 9242.382757] sd 8:0:0:0: [sdc] Assuming drive cache: write through
[ 9242.386877]  sdc:
[ 9242.396000] sd 8:0:0:0: [sdc] Attached SCSI removable disk
f3probe /dev/sdc
[ 9276.697035] usb 2-1: reset high-speed USB device number 3 using ehci-pci
[ 9276.915066]  sdc:
[ 9626.072637] usb usb2-port1: disabled by hub (EMI?), re-enabling...
[ 9626.078933] usb 2-1: USB disconnect, device number 3
[ 9626.085727] scsi 8:0:0:0: rejecting I/O to offline device
[ 9626.091235] scsi 8:0:0:0: [sdc] killing request
[ 9626.095846] scsi 8:0:0:0: rejecting I/O to offline device
[ 9626.101318] scsi 8:0:0:0: [sdc] killing request
[ 9626.106007] scsi 8:0:0:0: [sdc] FAILED Result: hostbyte=DID_NO_CONNECT driverbyte=DRIVER_OK
[ 9626.114400] scsi 8:0:0:0: [sdc] CDB: Read(10) 28 00 01 9e 2c b0 00 00 f0 00
[ 9626.121430] print_req_error: I/O error, dev sdc, sector 27143344
[ 9626.127523] scsi 8:0:0:0: [sdc] FAILED Result: hostbyte=DID_NO_CONNECT driverbyte=DRIVER_OK
[ 9626.135918] scsi 8:0:0:0: [sdc] CDB: Read(10) 28 00 01 9e 2d a0 00 00 f0 00
[ 9626.142918] print_req_error: I/O error, dev sdc, sector 27143584
[ 9787.760554] INFO: task kworker/0:1:63 blocked for more than 120 seconds.
[ 9787.767381]       Not tainted 4.15.0-rc2-debug-00490-gc09e9bbeb5d1 #1
[ 9787.773947] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 9787.781892] kworker/0:1     D    0    63      2 0x80000000
[ 9787.787495] Workqueue: usb_hub_wq hub_event
[ 9787.791760] Call Trace:
[ 9787.794277]  ? __schedule+0x1a5/0x6e0
[ 9787.798028]  schedule+0x23/0x80
[ 9787.801259]  blk_mq_freeze_queue_wait+0x31/0x80
[ 9787.805919]  ? wait_woken+0x80/0x80
[ 9787.809487]  blk_cleanup_queue+0x68/0x110
[ 9787.813614]  __scsi_remove_device+0x6f/0x150
[ 9787.818045]  scsi_forget_host+0x1b/0x60
[ 9787.821964]  scsi_remove_host+0x6d/0x100
[ 9787.825997]  usb_stor_disconnect+0x57/0xc0 [usb_storage]
[ 9787.831417]  usb_unbind_interface+0x6c/0x270
[ 9787.835787]  device_release_driver_internal+0x195/0x260
[ 9787.841125]  bus_remove_device+0xd4/0x120
[ 9787.845263]  device_del+0x11a/0x320
[ 9787.848802]  ? usb_remove_ep_devs+0x16/0x30
[ 9787.853073]  usb_disable_device+0x7b/0x1d0
[ 9787.857274]  usb_disconnect+0xb6/0x220
[ 9787.861145]  hub_event+0x733/0x1300
[ 9787.864698]  process_one_work+0x1a7/0x340
[ 9787.868811]  worker_thread+0x26/0x3f0
[ 9787.872630]  ? create_worker+0x190/0x190
[ 9787.876698]  kthread+0x107/0x120
[ 9787.879994]  ? kthread_create_worker_on_cpu+0x40/0x40
[ 9787.885143]  ret_from_fork+0x1f/0x30
[ 9787.888881] INFO: task f3probe:5269 blocked for more than 120 seconds.
[ 9787.895530]       Not tainted 4.15.0-rc2-debug-00490-gc09e9bbeb5d1 #1
[ 9787.902079] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 9787.910094] f3probe         D    0  5269   4476 0x00000000
[ 9787.915683] Call Trace:
[ 9787.918229]  ? __schedule+0x1a5/0x6e0
[ 9787.921956]  schedule+0x23/0x80
[ 9787.925182]  io_schedule+0xd/0x40
[ 9787.928575]  __blkdev_direct_IO_simple+0x1a2/0x2a0
[ 9787.933482]  ? bdget+0x110/0x110
[ 9787.936800]  blkdev_direct_IO+0x34c/0x390
[ 9787.940962]  ? current_time+0x11/0x60
[ 9787.944716]  ? generic_update_time+0x77/0xc0
[ 9787.949098]  ? current_time+0x11/0x60
[ 9787.952863]  generic_file_read_iter+0x9f/0x930
[ 9787.957465]  ? invalidate_mapping_pages+0x6d/0x2a0
[ 9787.962360]  ? lru_lazyfree_fn+0x2d0/0x2d0
[ 9787.966573]  ? release_pages+0x2a5/0x340
[ 9787.970565]  __vfs_read+0xcc/0x120
[ 9787.974054]  vfs_read+0x98/0x150
[ 9787.977359]  SyS_read+0x4b/0xb0
[ 9787.980583]  ? SyS_lseek+0x6e/0xc0
[ 9787.984035]  entry_SYSCALL_64_fastpath+0x17/0x70
[ 9787.988783] RIP: 0033:0x7fa6ab981750
[ 9787.992537] RSP: 002b:00007ffe29ce8568 EFLAGS: 00000246 ORIG_RAX: 0000000000000000
[ 9788.000294] RAX: ffffffffffffffda RBX: 00000000019e27fe RCX: 00007fa6ab981750
[ 9788.007525] RDX: 0000000000100000 RSI: 00007fa675184200 RDI: 0000000000000003
[ 9788.014858] RBP: 0000563803f9e4b0 R08: 00005638022efde0 R09: 0000000001d42000
[ 9788.022126] R10: 0000000000000004 R11: 0000000000000246 R12: 00000000019e27ff
[ 9788.029370] R13: 00007fa61eff3010 R14: 0000000000000001 R15: 00007fa61ec4a010
[ 9908.588627] INFO: task kworker/0:1:63 blocked for more than 120 seconds.
[ 9908.595451]       Not tainted 4.15.0-rc2-debug-00490-gc09e9bbeb5d1 #1
[ 9908.602076] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 9908.610015] kworker/0:1     D    0    63      2 0x80000000
[ 9908.615585] Workqueue: usb_hub_wq hub_event
[ 9908.619868] Call Trace:
[ 9908.622418]  ? __schedule+0x1a5/0x6e0
[ 9908.626189]  schedule+0x23/0x80
[ 9908.629463]  blk_mq_freeze_queue_wait+0x31/0x80
[ 9908.634117]  ? wait_woken+0x80/0x80
[ 9908.637704]  blk_cleanup_queue+0x68/0x110
[ 9908.641843]  __scsi_remove_device+0x6f/0x150
[ 9908.646232]  scsi_forget_host+0x1b/0x60
[ 9908.650159]  scsi_remove_host+0x6d/0x100
[ 9908.654210]  usb_stor_disconnect+0x57/0xc0 [usb_storage]
[ 9908.659690]  usb_unbind_interface+0x6c/0x270
[ 9908.664089]  device_release_driver_internal+0x195/0x260
[ 9908.669392]  bus_remove_device+0xd4/0x120
[ 9908.673504]  device_del+0x11a/0x320
[ 9908.677063]  ? usb_remove_ep_devs+0x16/0x30
[ 9908.681398]  usb_disable_device+0x7b/0x1d0
[ 9908.685588]  usb_disconnect+0xb6/0x220
[ 9908.689444]  hub_event+0x733/0x1300
[ 9908.693056]  process_one_work+0x1a7/0x340
[ 9908.697165]  worker_thread+0x26/0x3f0
[ 9908.700883]  ? create_worker+0x190/0x190
[ 9908.704940]  kthread+0x107/0x120
[ 9908.708236]  ? kthread_create_worker_on_cpu+0x40/0x40
[ 9908.713464]  ret_from_fork+0x1f/0x30
[ 9908.717240] INFO: task f3probe:5269 blocked for more than 120 seconds.
[ 9908.723965]       Not tainted 4.15.0-rc2-debug-00490-gc09e9bbeb5d1 #1
[ 9908.730527] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 9908.738539] f3probe         D    0  5269   4476 0x00000000
[ 9908.744162] Call Trace:
[ 9908.746698]  ? __schedule+0x1a5/0x6e0
[ 9908.750428]  schedule+0x23/0x80
[ 9908.753688]  io_schedule+0xd/0x40
[ 9908.757116]  __blkdev_direct_IO_simple+0x1a2/0x2a0
[ 9908.762020]  ? bdget+0x110/0x110
[ 9908.765345]  blkdev_direct_IO+0x34c/0x390
[ 9908.769466]  ? current_time+0x11/0x60
[ 9908.773216]  ? generic_update_time+0x77/0xc0
[ 9908.777578]  ? current_time+0x11/0x60
[ 9908.781315]  generic_file_read_iter+0x9f/0x930
[ 9908.785877]  ? invalidate_mapping_pages+0x6d/0x2a0
[ 9908.790810]  ? lru_lazyfree_fn+0x2d0/0x2d0
[ 9908.795037]  ? release_pages+0x2a5/0x340
[ 9908.799100]  __vfs_read+0xcc/0x120
[ 9908.802569]  vfs_read+0x98/0x150
[ 9908.805949]  SyS_read+0x4b/0xb0
[ 9908.809197]  ? SyS_lseek+0x6e/0xc0
[ 9908.812703]  entry_SYSCALL_64_fastpath+0x17/0x70
[ 9908.817396] RIP: 0033:0x7fa6ab981750
[ 9908.821093] RSP: 002b:00007ffe29ce8568 EFLAGS: 00000246 ORIG_RAX: 0000000000000000
[ 9908.828831] RAX: ffffffffffffffda RBX: 00000000019e27fe RCX: 00007fa6ab981750
[ 9908.836187] RDX: 0000000000100000 RSI: 00007fa675184200 RDI: 0000000000000003
[ 9908.843449] RBP: 0000563803f9e4b0 R08: 00005638022efde0 R09: 0000000001d42000
[ 9908.850706] R10: 0000000000000004 R11: 0000000000000246 R12: 00000000019e27ff
[ 9908.858042] R13: 00007fa61eff3010 R14: 0000000000000001 R15: 00007fa61ec4a010

with f3probe obviously stuck forever.  There's no extra messages on actually
physically removing the SD card or the reader.

With SD cards and USB sticks having floppy-like reliability, I/O failures
need to be considered a normal occurence, especially with no filesystem even
mounted.  In this case, the card offlines itself, but the removal doesn't
complete.


Meow!
-- 
// If you believe in so-called "intellectual property", please immediately
// cease using counterfeit alphabets.  Instead, contact the nearest temple
// of Amon, whose priests will provide you with scribal services for all
// your writing needs, for Reasonable And Non-Discriminatory prices.
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html



[Index of Archives]     [Linux Media]     [Linux Input]     [Linux Audio Users]     [Yosemite News]     [Linux Kernel]     [Linux SCSI]     [Old Linux USB Devel Archive]

  Powered by Linux