Re: Bug 207877: ASMedia drive (174c:55aa) hangs in ioctl CDROM_DRIVE_STATUS when mounting a DVD

[Alan Stern <stern@rowland.harvard.edu>]

On Thu, May 28, 2020 at 02:27:52PM -0500, Zebediah Figura wrote:
> On 5/28/20 12:05 PM, Alan Stern wrote:
> > I get the impression that the SCSI error handler may have tried to reset
> > the device without first aborting the current transfer.  But it's not
> > easy to tell if that's what really happened.  You might be able to get
> > more information by enabling CONFIG_USB_STORAGE_DEBUG and rebuilding the
> > usb-storage driver, or by turning on SCSI debugging.
> 
> I've attached a kernel log with CONFIG_USB_STORAGE_DEBUG to the bug report.
> I'm not able to properly interpret the results, but I do see "device_reset
> called" as the last USB/SCSI-related message without any nearby mention of
> cancellation...?
> 
> The backtrace looks different, though.

I don't think that matters.

> With respect to SCSI debugging, the best instructions I was able to find
> directed me to try:
> 
> hazel@watership:~$ cat /proc/scsi/sg/debug
> max_active_device=2  def_reserved_size=32768
> 
> while the hang was taking place. If there's more useful debugging I can do,
> I'll need pointers. I did enable CONFIG_SCSI_LOGGING in the above build.

Maybe someone from the linux-scsi mailing list will help.

Here is the problem we are facing, as shown in the following debugging 
log.  The log includes a sequence of six commands sent to a DVD drive.  
The first READ succeeds:

May 28 14:03:05 watership kernel: *** thread awakened
May 28 14:03:05 watership kernel: Command READ_10 (10 bytes)
May 28 14:03:05 watership kernel: bytes: 28 00 00 00 00 fa 00 00 06 00
May 28 14:03:05 watership kernel: Bulk Command S 0x43425355 T 0x222 L 12288 F 128 Trg 0 LUN 0 CL 10
May 28 14:03:05 watership kernel: xfer 31 bytes
May 28 14:03:05 watership kernel: Status code 0; transferred 31/31
May 28 14:03:05 watership kernel: -- transfer complete
May 28 14:03:05 watership kernel: Bulk command transfer result=0
May 28 14:03:05 watership kernel: xfer 12288 bytes, 1 entries
May 28 14:03:05 watership kernel: Status code 0; transferred 12288/12288
May 28 14:03:05 watership kernel: -- transfer complete
May 28 14:03:05 watership kernel: Bulk data transfer result 0x0
May 28 14:03:05 watership kernel: Attempting to get CSW...
May 28 14:03:05 watership kernel: xfer 13 bytes
May 28 14:03:05 watership kernel: Status code 0; transferred 13/13
May 28 14:03:05 watership kernel: -- transfer complete
May 28 14:03:05 watership kernel: Bulk status result = 0
May 28 14:03:05 watership kernel: Bulk Status S 0x53425355 T 0x222 R 0 Stat 0x0
May 28 14:03:05 watership kernel: scsi cmd done, result=0x0
May 28 14:03:05 watership kernel: *** thread sleeping

The second READ hangs for 30 seconds (reason unknown) and then gets 
aborted.  Following the abort, usb-storage automatically performs a 
reset:

May 28 14:03:05 watership kernel: *** thread awakened
May 28 14:03:05 watership kernel: Command READ_10 (10 bytes)
May 28 14:03:05 watership kernel: bytes: 28 00 00 3e 38 00 00 00 3c 00
May 28 14:03:05 watership kernel: Bulk Command S 0x43425355 T 0x223 L 122880 F 128 Trg 0 LUN 0 CL 10
May 28 14:03:05 watership kernel: xfer 31 bytes
May 28 14:03:05 watership kernel: Status code 0; transferred 31/31
May 28 14:03:05 watership kernel: -- transfer complete
May 28 14:03:05 watership kernel: Bulk command transfer result=0
May 28 14:03:05 watership kernel: xfer 122880 bytes, 15 entries
May 28 14:03:37 watership kernel: command_abort called
May 28 14:03:37 watership kernel: -- cancelling sg request
May 28 14:03:37 watership kernel: Status code -104; transferred 2048/122880
May 28 14:03:37 watership kernel: -- transfer cancelled
May 28 14:03:37 watership kernel: Bulk data transfer result 0x4
May 28 14:03:37 watership kernel: -- command was aborted
May 28 14:03:37 watership kernel: usb 1-5: reset high-speed USB device number 3 using xhci_hcd
May 28 14:03:37 watership kernel: usb_reset_device returns 0
May 28 14:03:37 watership kernel: scsi command aborted
May 28 14:03:37 watership kernel: *** thread sleeping
May 28 14:03:37 watership kernel: sr 1:0:0:0: [sr0] tag#0 FAILED Result: hostbyte=DID_TIME_OUT driverbyte=DRIVER_OK cmd_age=31s
May 28 14:03:37 watership kernel: sr 1:0:0:0: [sr0] tag#0 CDB: Read(10) 28 00 00 3e 38 00 00 00 3c 00
May 28 14:03:37 watership kernel: blk_update_request: I/O error, dev sr0, sector 16310272 op 0x0:(READ) flags 0x80700 phys_seg 15 prio class 0

Next is a GET EVENT/STATUS NOTIFICATION...

May 28 14:03:37 watership kernel: *** thread awakened
May 28 14:03:37 watership kernel: Command GET EVENT/STATUS NOTIFICATION (10 bytes)
May 28 14:03:37 watership kernel: bytes: 4a 01 00 00 10 00 00 00 08 00
May 28 14:03:37 watership kernel: Bulk Command S 0x43425355 T 0x224 L 8 F 128 Trg 0 LUN 0 CL 10
May 28 14:03:37 watership kernel: xfer 31 bytes
May 28 14:03:37 watership kernel: Status code 0; transferred 31/31
May 28 14:03:37 watership kernel: -- transfer complete
May 28 14:03:37 watership kernel: Bulk command transfer result=0
May 28 14:03:37 watership kernel: xfer 8 bytes, 1 entries
May 28 14:03:37 watership kernel: Status code 0; transferred 8/8
May 28 14:03:37 watership kernel: -- transfer complete
May 28 14:03:37 watership kernel: Bulk data transfer result 0x0
May 28 14:03:37 watership kernel: Attempting to get CSW...
May 28 14:03:37 watership kernel: xfer 13 bytes
May 28 14:03:37 watership kernel: Status code 0; transferred 13/13
May 28 14:03:37 watership kernel: -- transfer complete
May 28 14:03:37 watership kernel: Bulk status result = 0
May 28 14:03:37 watership kernel: Bulk Status S 0x53425355 T 0x224 R 0 Stat 0x0
May 28 14:03:37 watership kernel: scsi cmd done, result=0x0
May 28 14:03:37 watership kernel: *** thread sleeping

... followed by a retry attempt of the previous READ, which hangs and is 
aborted again:

May 28 14:03:37 watership kernel: *** thread awakened
May 28 14:03:37 watership kernel: Command READ_10 (10 bytes)
May 28 14:03:37 watership kernel: bytes: 28 00 00 3e 38 00 00 00 02 00
May 28 14:03:37 watership kernel: Bulk Command S 0x43425355 T 0x225 L 4096 F 128 Trg 0 LUN 0 CL 10
May 28 14:03:37 watership kernel: xfer 31 bytes
May 28 14:03:37 watership kernel: Status code 0; transferred 31/31
May 28 14:03:37 watership kernel: -- transfer complete
May 28 14:03:37 watership kernel: Bulk command transfer result=0
May 28 14:03:37 watership kernel: xfer 4096 bytes, 1 entries
May 28 14:04:08 watership kernel: command_abort called
May 28 14:04:08 watership kernel: -- cancelling sg request
May 28 14:04:08 watership kernel: Status code -104; transferred 2048/4096
May 28 14:04:08 watership kernel: -- transfer cancelled
May 28 14:04:08 watership kernel: Bulk data transfer result 0x4
May 28 14:04:08 watership kernel: -- command was aborted
May 28 14:04:08 watership kernel: usb 1-5: reset high-speed USB device number 3 using xhci_hcd
May 28 14:04:08 watership kernel: usb_reset_device returns 0
May 28 14:04:08 watership kernel: scsi command aborted
May 28 14:04:08 watership kernel: *** thread sleeping

Then there's another successful GET EVENT/STATUS NOTIFICATION:

May 28 14:04:08 watership kernel: *** thread awakened
May 28 14:04:08 watership kernel: Command GET EVENT/STATUS NOTIFICATION (10 bytes)
May 28 14:04:08 watership kernel: bytes: 4a 01 00 00 10 00 00 00 08 00
May 28 14:04:08 watership kernel: Bulk Command S 0x43425355 T 0x226 L 8 F 128 Trg 0 LUN 0 CL 10
May 28 14:04:08 watership kernel: xfer 31 bytes
May 28 14:04:08 watership kernel: Status code 0; transferred 31/31
May 28 14:04:08 watership kernel: -- transfer complete
May 28 14:04:08 watership kernel: Bulk command transfer result=0
May 28 14:04:08 watership kernel: xfer 8 bytes, 1 entries
May 28 14:04:08 watership kernel: Status code 0; transferred 8/8
May 28 14:04:08 watership kernel: -- transfer complete
May 28 14:04:08 watership kernel: Bulk data transfer result 0x0
May 28 14:04:08 watership kernel: Attempting to get CSW...
May 28 14:04:08 watership kernel: xfer 13 bytes
May 28 14:04:08 watership kernel: Status code 0; transferred 13/13
May 28 14:04:08 watership kernel: -- transfer complete
May 28 14:04:08 watership kernel: Bulk status result = 0
May 28 14:04:08 watership kernel: Bulk Status S 0x53425355 T 0x226 R 0 Stat 0x0
May 28 14:04:08 watership kernel: scsi cmd done, result=0x0
May 28 14:04:08 watership kernel: *** thread sleeping

And a third attempt at the READ, which hangs as before:

May 28 14:04:08 watership kernel: *** thread awakened
May 28 14:04:08 watership kernel: Command READ_10 (10 bytes)
May 28 14:04:08 watership kernel: bytes: 28 00 00 3e 38 00 00 00 02 00
May 28 14:04:08 watership kernel: Bulk Command S 0x43425355 T 0x227 L 4096 F 128 Trg 0 LUN 0 CL 10
May 28 14:04:08 watership kernel: xfer 31 bytes
May 28 14:04:08 watership kernel: Status code 0; transferred 31/31
May 28 14:04:08 watership kernel: -- transfer complete
May 28 14:04:08 watership kernel: Bulk command transfer result=0
May 28 14:04:08 watership kernel: xfer 4096 bytes, 1 entries

But this time, instead of aborting the command, the SCSI core calls the 
device_reset routine.  This causes usb-storage to lock up; the reset 
can't proceed while the READ command is still executing:

May 28 14:04:38 watership kernel: device_reset called
May 28 14:06:48 watership kernel: INFO: task scsi_eh_1:240 blocked for more than 122 seconds.
May 28 14:06:48 watership kernel:       Not tainted 5.7.0-rc7local #4
May 28 14:06:48 watership kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
May 28 14:06:48 watership kernel: scsi_eh_1       D    0   240      2 0x80004000
May 28 14:06:48 watership kernel: Call Trace:
May 28 14:06:48 watership kernel:  __schedule+0x2a5/0x8c0
May 28 14:06:48 watership kernel:  schedule+0x46/0xf0
May 28 14:06:48 watership kernel:  schedule_preempt_disabled+0x14/0x20
May 28 14:06:48 watership kernel:  __mutex_lock.constprop.0+0x180/0x510
May 28 14:06:48 watership kernel:  device_reset+0x33/0x60 [usb_storage]
May 28 14:06:48 watership kernel:  scsi_eh_ready_devs+0x5f4/0xa40 [scsi_mod]
May 28 14:06:48 watership kernel:  ? _raw_spin_unlock_irqrestore+0x20/0x40
May 28 14:06:48 watership kernel:  ? __pm_runtime_resume+0x49/0x60
May 28 14:06:48 watership kernel:  scsi_error_handler+0x448/0x510 [scsi_mod]
May 28 14:06:48 watership kernel:  ? scsi_eh_get_sense+0x1f0/0x1f0 [scsi_mod]
May 28 14:06:48 watership kernel:  kthread+0x13e/0x160
May 28 14:06:48 watership kernel:  ? __kthread_bind_mask+0x60/0x60
May 28 14:06:48 watership kernel:  ret_from_fork+0x22/0x40
May 28 14:06:48 watership kernel: INFO: task usb-storage:242 blocked for more than 122 seconds.
May 28 14:06:48 watership kernel:       Not tainted 5.7.0-rc7local #4
May 28 14:06:48 watership kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
May 28 14:06:48 watership kernel: usb-storage     D    0   242      2 0x80004000
May 28 14:06:48 watership kernel: Call Trace:
May 28 14:06:48 watership kernel:  __schedule+0x2a5/0x8c0
May 28 14:06:48 watership kernel:  schedule+0x46/0xf0
May 28 14:06:48 watership kernel:  schedule_timeout+0x12d/0x170
May 28 14:06:48 watership kernel:  wait_for_completion+0x9e/0x100
May 28 14:06:48 watership kernel:  usb_sg_wait+0xc9/0x190
May 28 14:06:48 watership kernel:  usb_stor_bulk_transfer_sglist.part.0.constprop.0+0x7f/0x100 [usb_storage]
May 28 14:06:48 watership kernel:  ? fill_inquiry_response+0x10/0x10 [usb_storage]
May 28 14:06:48 watership kernel:  usb_stor_Bulk_transport+0x1f9/0x5b0 [usb_storage]
May 28 14:06:48 watership kernel:  ? fill_inquiry_response+0x10/0x10 [usb_storage]
May 28 14:06:48 watership kernel:  usb_stor_invoke_transport+0x59/0x6c0 [usb_storage]
May 28 14:06:48 watership kernel:  ? fill_inquiry_response+0x10/0x10 [usb_storage]
May 28 14:06:48 watership kernel:  usb_stor_control_thread+0x17d/0x390 [usb_storage]
May 28 14:06:48 watership kernel:  kthread+0x13e/0x160
May 28 14:06:48 watership kernel:  ? __kthread_bind_mask+0x60/0x60
May 28 14:06:48 watership kernel:  ret_from_fork+0x22/0x40

So here's the question: Why doesn't the SCSI error handler abort the 
ongoing command (like it did the first two times) before resetting the 
device?

Note: The kernel version is 5.7-rc7.

Alan Stern