Reproducible deadlock when usb-storage scsi command timeouts twice

PATCH Maxime Bizon 5 participants 14 messages Apr 26, 2023 – May 4, 2023

Subsystems (3)

SCSI USB USB mass storage driver

lore

Share & tools

lore

Maxime Bizon

author

2023-04-26 17:55 UTC #0 lore raw

Hello,

I have a faulty 128MB USB stick that happens to randomly timeout when reading a specific block.

After the first timeout, the scsi layer retries the command. If that retry work, then everything goes well. But if the retried command timeouts as well, then I get a deadlock.

To reproduce fast & reliable, I'm using these settings:

# echo 10 >/proc/sys/kernel/hung_task_timeout_secs
# echo 0x3f > /proc/sys/dev/scsi/logging_level
# cd /sys/block/sda/queue/
# echo none > scheduler
# echo 1 > nr_requests
# echo 1 > nomerges
# echo 4 > max_sectors_kb
# echo 5000 > io_timeout
# cat /dev/sda > /dev/null

dmesg with timestamps so it's easy to spot the timeouts:

[  211.732418] *** thread awakened
[  211.732429] Command READ_10 (10 bytes)
[  211.732438] bytes: 28 00 00 02 01 f8 00 00 08 00
[  211.732447] Bulk Command S 0x43425355 T 0xb8ca L 4096 F 128 Trg 0 LUN 0 CL 10
[  211.732459] xfer 31 bytes
[  211.732539] Status code 0; transferred 31/31
[  211.732550] -- transfer complete
[  211.732557] Bulk command transfer result=0
[  211.732564] xfer 4096 bytes, 1 entries
[  211.732913] Status code 0; transferred 4096/4096
[  211.732925] -- transfer complete
[  211.732931] Bulk data transfer result 0x0
[  211.732938] Attempting to get CSW...
[  211.732944] xfer 13 bytes
[  211.733036] Status code 0; transferred 13/13
[  211.733047] -- transfer complete
[  211.733054] Bulk status result = 0
[  211.733061] Bulk Status S 0x53425355 T 0xb8ca R 0 Stat 0x0
[  211.733071] scsi cmd done, result=0x0
[  211.733092] *** thread sleeping
[  211.733162] *** thread awakened
[  211.733174] Command READ_10 (10 bytes)
[  211.733183] bytes: 28 00 00 02 02 00 00 00 08 00
[  211.733192] Bulk Command S 0x43425355 T 0xb8cb L 4096 F 128 Trg 0 LUN 0 CL 10
[  211.733204] xfer 31 bytes
[  211.733288] Status code 0; transferred 31/31
[  211.733300] -- transfer complete
[  211.733306] Bulk command transfer result=0
[  211.733313] xfer 4096 bytes, 1 entries
[  218.089304] sd 0:0:0:0: [sda] tag#0 abort scheduled
[  218.109297] sd 0:0:0:0: [sda] tag#0 aborting command
[  218.109315] command_abort called
[  218.109324] -- cancelling sg request
[  218.112380] Status code -104; transferred 3072/4096
[  218.112393] -- transfer cancelled
[  218.112400] Bulk data transfer result 0x4
[  218.112407] -- command was aborted
[  218.209278] usb 1-1.2: reset high-speed USB device number 3 using orion-ehci
[  218.359923] usb_reset_device returns 0
[  218.359936] scsi command aborted
[  218.359947] *** thread sleeping
[  218.359964] sd 0:0:0:0: [sda] tag#0 retry aborted command
[  218.399298] *** thread awakened
[  218.399311] Command READ_10 (10 bytes)
[  218.399320] bytes: 28 00 00 02 02 00 00 00 08 00
[  218.399330] Bulk Command S 0x43425355 T 0xb8cc L 4096 F 128 Trg 0 LUN 0 CL 10
[  218.399342] xfer 31 bytes
[  218.399544] Status code 0; transferred 31/31
[  218.399556] -- transfer complete
[  218.399562] Bulk command transfer result=0
[  218.399570] xfer 4096 bytes, 1 entries
[  225.129297] sd 0:0:0:0: [sda] tag#0 previous abort failed
[  225.129337] scsi host0: Waking error handler thread
[  225.129358] scsi host0: scsi_eh_0: waking up 0/1/1
[  225.129375] scsi host0: scsi_eh_prt_fail_stats: cmds failed: 0, cancel: 1
[  225.129387] scsi host0: Total of 1 commands on 1 devices require eh work
[  225.129402] sd 0:0:0:0: scsi_eh_0: Sending BDR
[  225.129414] device_reset called
[  235.369290] INFO: task scsi_eh_0:173 blocked for more than 10 seconds.
[  235.369311]       Not tainted 6.3.0-00615-gffe64935a4a2 #9
[  235.369320] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  235.369327] task:scsi_eh_0       state:D stack:0     pid:173   ppid:2      flags:0x00000000
[  235.369350]  __schedule from schedule+0x70/0xac
[  235.369374]  schedule from schedule_preempt_disabled+0x24/0x34
[  235.369393]  schedule_preempt_disabled from __mutex_lock.constprop.0+0x14c/0x280
[  235.369412]  __mutex_lock.constprop.0 from device_reset+0x28/0x64
[  235.369433]  device_reset from scsi_try_bus_device_reset+0x24/0x58
[  235.369452]  scsi_try_bus_device_reset from scsi_eh_ready_devs+0x2f0/0x97c
[  235.369470]  scsi_eh_ready_devs from scsi_error_handler+0x238/0x49c
[  235.369488]  scsi_error_handler from kthread+0xc4/0xdc
[  235.369507]  kthread from ret_from_fork+0x14/0x3c
[  235.369567] INFO: task usb-storage:176 blocked for more than 10 seconds.
[  235.369576]       Not tainted 6.3.0-00615-gffe64935a4a2 #9
[  235.369583] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  235.369590] task:usb-storage     state:D stack:0     pid:176   ppid:2      flags:0x00000000
[  235.369606]  __schedule from schedule+0x70/0xac
[  235.369622]  schedule from schedule_timeout+0x18/0xd0
[  235.369641]  schedule_timeout from __wait_for_common+0xc0/0x13c
[  235.369660]  __wait_for_common from usb_sg_wait+0x10c/0x118
[  235.369677]  usb_sg_wait from usb_stor_bulk_transfer_sglist+0xc4/0x118
[  235.369695]  usb_stor_bulk_transfer_sglist from usb_stor_bulk_srb+0x24/0x3c
[  235.369713]  usb_stor_bulk_srb from usb_stor_Bulk_transport+0x164/0x44c
[  235.369731]  usb_stor_Bulk_transport from usb_stor_invoke_transport+0x20/0x5c4
[  235.369750]  usb_stor_invoke_transport from usb_stor_control_thread+0x1a4/0x2bc
[  235.369769]  usb_stor_control_thread from kthread+0xc4/0xdc
[  235.369786]  kthread from ret_from_fork+0x14/0x3c

Turns out eh_device_reset_handler() is called with a pending command (srb == us->srb), and I don't know if the usb code was expecting eh_abort_handler() to be called first.

This patch fixes the issue, not sure if it's correct:

drivers/usb/storage/scsiglue.c +3 -0

@@ -455,6 +455,9 @@ static int device_reset(struct scsi_cmnd *srb)
 
        usb_stor_dbg(us, "%s called\n", __func__);
 
+       if (us->srb == srb)
+               command_abort(srb);
+
        /* lock the device pointers and do the reset */
        mutex_lock(&(us->dev_mutex));
        result = us->transport_reset(us);

Signature · 1 line

Maxime

Alan Stern

maintainer

2023-04-26 19:20 UTC #1 lore raw

[Adding linux-scsi and Martin to the CC: list, since this looks like it might be a problem in the SCSI core]

Quoted 9 lines · Maxime Bizon

Hello,
I have a faulty 128MB USB stick that happens to randomly timeout when reading a specific block.
After the first timeout, the scsi layer retries the command. If that retry work, then everything goes well. But if the retried command timeouts as well, then I get a deadlock.

What version of the kernel are you using?

Quoted 83 lines

To reproduce fast & reliable, I'm using these settings:

# echo 10 >/proc/sys/kernel/hung_task_timeout_secs
# echo 0x3f > /proc/sys/dev/scsi/logging_level
# cd /sys/block/sda/queue/
# echo none > scheduler
# echo 1 > nr_requests
# echo 1 > nomerges
# echo 4 > max_sectors_kb
# echo 5000 > io_timeout
# cat /dev/sda > /dev/null

dmesg with timestamps so it's easy to spot the timeouts:

[  211.733162] *** thread awakened
[  211.733174] Command READ_10 (10 bytes)
[  211.733183] bytes: 28 00 00 02 02 00 00 00 08 00
[  211.733192] Bulk Command S 0x43425355 T 0xb8cb L 4096 F 128 Trg 0 LUN 0 CL 10
[  211.733204] xfer 31 bytes
[  211.733288] Status code 0; transferred 31/31
[  211.733300] -- transfer complete
[  211.733306] Bulk command transfer result=0
[  211.733313] xfer 4096 bytes, 1 entries
[  218.089304] sd 0:0:0:0: [sda] tag#0 abort scheduled
[  218.109297] sd 0:0:0:0: [sda] tag#0 aborting command
[  218.109315] command_abort called
[  218.109324] -- cancelling sg request
[  218.112380] Status code -104; transferred 3072/4096
[  218.112393] -- transfer cancelled
[  218.112400] Bulk data transfer result 0x4
[  218.112407] -- command was aborted
[  218.209278] usb 1-1.2: reset high-speed USB device number 3 using orion-ehci
[  218.359923] usb_reset_device returns 0
[  218.359936] scsi command aborted
[  218.359947] *** thread sleeping
[  218.359964] sd 0:0:0:0: [sda] tag#0 retry aborted command
[  218.399298] *** thread awakened
[  218.399311] Command READ_10 (10 bytes)
[  218.399320] bytes: 28 00 00 02 02 00 00 00 08 00
[  218.399330] Bulk Command S 0x43425355 T 0xb8cc L 4096 F 128 Trg 0 LUN 0 CL 10
[  218.399342] xfer 31 bytes
[  218.399544] Status code 0; transferred 31/31
[  218.399556] -- transfer complete
[  218.399562] Bulk command transfer result=0
[  218.399570] xfer 4096 bytes, 1 entries
[  225.129297] sd 0:0:0:0: [sda] tag#0 previous abort failed
[  225.129337] scsi host0: Waking error handler thread
[  225.129358] scsi host0: scsi_eh_0: waking up 0/1/1
[  225.129375] scsi host0: scsi_eh_prt_fail_stats: cmds failed: 0, cancel: 1
[  225.129387] scsi host0: Total of 1 commands on 1 devices require eh work
[  225.129402] sd 0:0:0:0: scsi_eh_0: Sending BDR
[  225.129414] device_reset called
[  235.369290] INFO: task scsi_eh_0:173 blocked for more than 10 seconds.
[  235.369311]       Not tainted 6.3.0-00615-gffe64935a4a2 #9
[  235.369320] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  235.369327] task:scsi_eh_0       state:D stack:0     pid:173   ppid:2      flags:0x00000000
[  235.369350]  __schedule from schedule+0x70/0xac
[  235.369374]  schedule from schedule_preempt_disabled+0x24/0x34
[  235.369393]  schedule_preempt_disabled from __mutex_lock.constprop.0+0x14c/0x280
[  235.369412]  __mutex_lock.constprop.0 from device_reset+0x28/0x64
[  235.369433]  device_reset from scsi_try_bus_device_reset+0x24/0x58
[  235.369452]  scsi_try_bus_device_reset from scsi_eh_ready_devs+0x2f0/0x97c
[  235.369470]  scsi_eh_ready_devs from scsi_error_handler+0x238/0x49c
[  235.369488]  scsi_error_handler from kthread+0xc4/0xdc
[  235.369507]  kthread from ret_from_fork+0x14/0x3c
[  235.369567] INFO: task usb-storage:176 blocked for more than 10 seconds.
[  235.369576]       Not tainted 6.3.0-00615-gffe64935a4a2 #9
[  235.369583] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  235.369590] task:usb-storage     state:D stack:0     pid:176   ppid:2      flags:0x00000000
[  235.369606]  __schedule from schedule+0x70/0xac
[  235.369622]  schedule from schedule_timeout+0x18/0xd0
[  235.369641]  schedule_timeout from __wait_for_common+0xc0/0x13c
[  235.369660]  __wait_for_common from usb_sg_wait+0x10c/0x118
[  235.369677]  usb_sg_wait from usb_stor_bulk_transfer_sglist+0xc4/0x118
[  235.369695]  usb_stor_bulk_transfer_sglist from usb_stor_bulk_srb+0x24/0x3c
[  235.369713]  usb_stor_bulk_srb from usb_stor_Bulk_transport+0x164/0x44c
[  235.369731]  usb_stor_Bulk_transport from usb_stor_invoke_transport+0x20/0x5c4
[  235.369750]  usb_stor_invoke_transport from usb_stor_control_thread+0x1a4/0x2bc
[  235.369769]  usb_stor_control_thread from kthread+0xc4/0xdc
[  235.369786]  kthread from ret_from_fork+0x14/0x3c

Quoted 3 lines

Turns out eh_device_reset_handler() is called with a pending command (srb == us->srb), and I don't know if the usb code was expecting eh_abort_handler() to be called first.

usb-storage definitely expects any pending command to be aborted before a reset is attempted.

Quoted 5 lines

This patch fixes the issue, not sure if it's correct:

drivers/usb/storage/scsiglue.c static int device_reset(struct scsi_cmnd *srb) · line 463

Quoted 9 lines

drivers/usb/storage/scsiglue.c +3 -0

@@ -455,6 +455,9 @@ static int device_reset(struct scsi_cmnd *srb)
 
        usb_stor_dbg(us, "%s called\n", __func__);
 
+       if (us->srb == srb)
+               command_abort(srb);
+
        /* lock the device pointers and do the reset */
        mutex_lock(&(us->dev_mutex));
        result = us->transport_reset(us);

Maybe... But it would be better to check first whether the SCSI core is supposed to be reusing an active srb in this way.

Martin, can tell us what is supposed to happen here? Is the eh_device_reset_handler routine supposed to be called with a scsi_cmnd for a currently active command?

Alan Stern

Maxime Bizon

author

2023-04-26 23:07 UTC #2 lore raw

Quoted 1 line · Alan Stern

What version of the kernel are you using?

6.3

Signature · 1 line

Maxime

Bart Van Assche

2023-04-30 19:39 UTC #3 lore raw

In reply to Alan Stern

Quoted 18 lines · Alan Stern

Quoted 5 lines
This patch fixes the issue, not sure if it's correct:
drivers/usb/storage/scsiglue.c static int device_reset(struct scsi_cmnd *srb) · line 463
Quoted 9 lines
drivers/usb/storage/scsiglue.c +3 -0
@@ -455,6 +455,9 @@ static int device_reset(struct scsi_cmnd *srb)
 
         usb_stor_dbg(us, "%s called\n", __func__);
 
+       if (us->srb == srb)
+               command_abort(srb);
+
         /* lock the device pointers and do the reset */
         mutex_lock(&(us->dev_mutex));
         result = us->transport_reset(us);
Maybe... But it would be better to check first whether the SCSI core is supposed to be reusing an active srb in this way.

Quoted 3 lines

Martin, can tell us what is supposed to happen here? Is the eh_device_reset_handler routine supposed to be called with a scsi_cmnd for a currently active command?

Hi Alan,

I'm not aware of any other .eh_device_reset_handler implementation that aborts the command that is passed to this callback before it aborts other SCSI commands. However, I'm not aware of an equivalent of us_data.dev_mutex in other SCSI LLDs either. Maybe this deadlock is specific to the USB storage handler?

Martin, feel free to correct me if I got anything wrong.

Bart.

Alan Stern

maintainer

2023-04-30 21:10 UTC #4 lore raw

Quoted 21 lines · Bart Van Assche

Quoted 16 lines · Alan Stern
drivers/usb/storage/scsiglue.c static int device_reset(struct scsi_cmnd *srb) · line 461
Quoted 12 lines
This patch fixes the issue, not sure if it's correct:
drivers/usb/storage/scsiglue.c +3 -0
@@ -455,6 +455,9 @@ static int device_reset(struct scsi_cmnd *srb)
         usb_stor_dbg(us, "%s called\n", __func__);
+       if (us->srb == srb)
+               command_abort(srb);
+
         /* lock the device pointers and do the reset */
         mutex_lock(&(us->dev_mutex));
         result = us->transport_reset(us);
Maybe... But it would be better to check first whether the SCSI core is supposed to be reusing an active srb in this way.
Quoted 3 lines
Martin, can tell us what is supposed to happen here? Is the eh_device_reset_handler routine supposed to be called with a scsi_cmnd for a currently active command?

Quoted 5 lines

Hi Alan,
I'm not aware of any other .eh_device_reset_handler implementation that aborts the command that is passed to this callback before it aborts other SCSI commands.

That's not a good description of what's happening. For one thing, usb-storage can process only one command at a time, so the "before it aborts other SCSI commands" part doesn't apply. In fact, the proposed patch aborts the current command (which happens to be the same as the one passed to the .eh_device_reset_handler routine) before beginning a reset.

Quoted 3 lines

However, I'm not aware of an equivalent of us_data.dev_mutex
in other SCSI LLDs either. Maybe this deadlock is specific to the USB storage handler?

The deadlock, if that's what it is, is related to the fact that usb-storage does only one thing at a time. The mutex is there merely to enforce this; removing it wouldn't help matters since the driver still wouldn't be capable of doing more than one thing at a time.

The underlying unstated issue is that usb-storage doesn't have any timeouts of its own. If a device fails to complete a command properly and the SCSI error handler doesn't abort the command, then the command will never finish and the driver will hang. (Until the device is hot-unplugged, of course.)

I suppose a bus reset would probably cause an ongoing command to fail. A device reset almost certainly would not, since most device implementations of the USB bulk-only mass-storage protocol do a very bad job of handling device resets.

Either way, it's a lot cleaner simply to abort the command before starting the reset. If usb-storage can't depend on the SCSI error handler to do this for us, it will have to do so itself.

Alan Stern

Quoted 3 lines

Martin, feel free to correct me if I got anything wrong.
Bart.

Benjamin Block

2023-05-03 10:25 UTC #5 lore raw

In reply to Alan Stern

Quoted 70 lines · Alan Stern

Quoted 70 lines

dmesg with timestamps so it's easy to spot the timeouts:

[  211.733162] *** thread awakened
[  211.733174] Command READ_10 (10 bytes)
[  211.733183] bytes: 28 00 00 02 02 00 00 00 08 00
[  211.733192] Bulk Command S 0x43425355 T 0xb8cb L 4096 F 128 Trg 0 LUN 0 CL 10
[  211.733204] xfer 31 bytes
[  211.733288] Status code 0; transferred 31/31
[  211.733300] -- transfer complete
[  211.733306] Bulk command transfer result=0
[  211.733313] xfer 4096 bytes, 1 entries
[  218.089304] sd 0:0:0:0: [sda] tag#0 abort scheduled
[  218.109297] sd 0:0:0:0: [sda] tag#0 aborting command
[  218.109315] command_abort called
[  218.109324] -- cancelling sg request
[  218.112380] Status code -104; transferred 3072/4096
[  218.112393] -- transfer cancelled
[  218.112400] Bulk data transfer result 0x4
[  218.112407] -- command was aborted
[  218.209278] usb 1-1.2: reset high-speed USB device number 3 using orion-ehci
[  218.359923] usb_reset_device returns 0
[  218.359936] scsi command aborted
[  218.359947] *** thread sleeping
[  218.359964] sd 0:0:0:0: [sda] tag#0 retry aborted command
[  218.399298] *** thread awakened
[  218.399311] Command READ_10 (10 bytes)
[  218.399320] bytes: 28 00 00 02 02 00 00 00 08 00
[  218.399330] Bulk Command S 0x43425355 T 0xb8cc L 4096 F 128 Trg 0 LUN 0 CL 10
[  218.399342] xfer 31 bytes
[  218.399544] Status code 0; transferred 31/31
[  218.399556] -- transfer complete
[  218.399562] Bulk command transfer result=0
[  218.399570] xfer 4096 bytes, 1 entries
[  225.129297] sd 0:0:0:0: [sda] tag#0 previous abort failed
[  225.129337] scsi host0: Waking error handler thread
[  225.129358] scsi host0: scsi_eh_0: waking up 0/1/1
[  225.129375] scsi host0: scsi_eh_prt_fail_stats: cmds failed: 0, cancel: 1
[  225.129387] scsi host0: Total of 1 commands on 1 devices require eh work
[  225.129402] sd 0:0:0:0: scsi_eh_0: Sending BDR
[  225.129414] device_reset called
[  235.369290] INFO: task scsi_eh_0:173 blocked for more than 10 seconds.
[  235.369311]       Not tainted 6.3.0-00615-gffe64935a4a2 #9
[  235.369320] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  235.369327] task:scsi_eh_0       state:D stack:0     pid:173   ppid:2      flags:0x00000000
[  235.369350]  __schedule from schedule+0x70/0xac
[  235.369374]  schedule from schedule_preempt_disabled+0x24/0x34
[  235.369393]  schedule_preempt_disabled from __mutex_lock.constprop.0+0x14c/0x280
[  235.369412]  __mutex_lock.constprop.0 from device_reset+0x28/0x64
[  235.369433]  device_reset from scsi_try_bus_device_reset+0x24/0x58
[  235.369452]  scsi_try_bus_device_reset from scsi_eh_ready_devs+0x2f0/0x97c
[  235.369470]  scsi_eh_ready_devs from scsi_error_handler+0x238/0x49c
[  235.369488]  scsi_error_handler from kthread+0xc4/0xdc
[  235.369507]  kthread from ret_from_fork+0x14/0x3c
[  235.369567] INFO: task usb-storage:176 blocked for more than 10 seconds.
[  235.369576]       Not tainted 6.3.0-00615-gffe64935a4a2 #9
[  235.369583] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  235.369590] task:usb-storage     state:D stack:0     pid:176   ppid:2      flags:0x00000000
[  235.369606]  __schedule from schedule+0x70/0xac
[  235.369622]  schedule from schedule_timeout+0x18/0xd0
[  235.369641]  schedule_timeout from __wait_for_common+0xc0/0x13c
[  235.369660]  __wait_for_common from usb_sg_wait+0x10c/0x118
[  235.369677]  usb_sg_wait from usb_stor_bulk_transfer_sglist+0xc4/0x118
[  235.369695]  usb_stor_bulk_transfer_sglist from usb_stor_bulk_srb+0x24/0x3c
[  235.369713]  usb_stor_bulk_srb from usb_stor_Bulk_transport+0x164/0x44c
[  235.369731]  usb_stor_Bulk_transport from usb_stor_invoke_transport+0x20/0x5c4
[  235.369750]  usb_stor_invoke_transport from usb_stor_control_thread+0x1a4/0x2bc
[  235.369769]  usb_stor_control_thread from kthread+0xc4/0xdc
[  235.369786]  kthread from ret_from_fork+0x14/0x3c

Quoted 6 lines

Quoted 3 lines
Turns out eh_device_reset_handler() is called with a pending command (srb == us->srb), and I don't know if the usb code was expecting eh_abort_handler() to be called first.
usb-storage definitely expects any pending command to be aborted before a reset is attempted.

From a cursory look at the logs above, SCSI ML does just try that:

Quoted 2 lines

[  218.089304] sd 0:0:0:0: [sda] tag#0 abort scheduled
[  218.109297] sd 0:0:0:0: [sda] tag#0 aborting command

calls hostt->eh_abort_handler() on the late request, and retries it after success.

Quoted 2 lines

[  218.359964] sd 0:0:0:0: [sda] tag#0 retry aborted command
[  225.129297] sd 0:0:0:0: [sda] tag#0 previous abort failed

but it times out again, then we go straight into EH:

Quoted 5 lines

[  225.129337] scsi host0: Waking error handler thread
[  225.129358] scsi host0: scsi_eh_0: waking up 0/1/1
[  225.129375] scsi host0: scsi_eh_prt_fail_stats: cmds failed: 0, cancel: 1
[  225.129387] scsi host0: Total of 1 commands on 1 devices require eh work
[  225.129402] sd 0:0:0:0: scsi_eh_0: Sending BDR

IIRC in the past we used to call Abort a second time from within the EH thread before trying the different resets, but that was removed at some point a couple of years ago. Now we add the command straight to the EH list, and start with the TMF LUN reset, which ought to implicitly abort the command as well on the target.

Quoted 8 lines

Quoted 8 lines
This patch fixes the issue, not sure if it's correct:
drivers/usb/storage/scsiglue.c +0 -0
@@ -455,6 +455,9 @@ static int device_reset(struct scsi_cmnd *srb)
 
        usb_stor_dbg(us, "%s called\n", __func__);
 

Quoted 9 lines

drivers/usb/storage/scsiglue.c static int device_reset(struct scsi_cmnd *srb) · line 463
Quoted 6 lines
drivers/usb/storage/scsiglue.c +3 -0
+       if (us->srb == srb)
+               command_abort(srb);
+
        /* lock the device pointers and do the reset */
        mutex_lock(&(us->dev_mutex));
        result = us->transport_reset(us);
Maybe... But it would be better to check first whether the SCSI core is supposed to be reusing an active srb in this way.

IIRC it does indeed doe that by design. It saves the old command's meta-data, and piggy-backs the TMF onto the existing request to push it into the device driver.

Hannes probably knows the complete story.

Quoted 4 lines

Martin, can tell us what is supposed to happen here? Is the eh_device_reset_handler routine supposed to be called with a scsi_cmnd for a currently active command?

Signature · 4 lines

Best Regards, Benjamin Block        /        Linux on IBM Z Kernel Development
IBM Deutschland Research & Development GmbH    /   https://www.ibm.com/privacy
Vors. Aufs.-R.: Gregor Pillen         /         Geschäftsführung: David Faller
Sitz der Ges.: Böblingen     /    Registergericht: AmtsG Stuttgart, HRB 243294

Oliver Neukum

2023-05-03 10:55 UTC #6 lore raw

Quoted 7 lines · Benjamin Block

On Wed, Apr 26, 2023 at 03:20:07PM -0400, Alan Stern wrote:
From a cursory look at the logs above, SCSI ML does just try that:
Quoted 2 lines
Quoted 2 lines
[  218.089304] sd 0:0:0:0: [sda] tag#0 abort scheduled
[  218.109297] sd 0:0:0:0: [sda] tag#0 aborting command

Quoted 7 lines

calls hostt->eh_abort_handler() on the late request, and retries it after success.
Quoted 2 lines
Quoted 2 lines
[  218.359964] sd 0:0:0:0: [sda] tag#0 retry aborted command
[  225.129297] sd 0:0:0:0: [sda] tag#0 previous abort failed
but it times out again, then we go straight into EH:

And that is problematic to usb-storage

Quoted 7 lines

Quoted 6 lines

[  225.129337] scsi host0: Waking error handler thread
[  225.129358] scsi host0: scsi_eh_0: waking up 0/1/1
[  225.129375] scsi host0: scsi_eh_prt_fail_stats: cmds failed: 0, cancel: 1
[  225.129387] scsi host0: Total of 1 commands on 1 devices require eh work
[  225.129402] sd 0:0:0:0: scsi_eh_0: Sending BDR

Quoted 5 lines

IIRC in the past we used to call Abort a second time from within the EH thread before trying the different resets, but that was removed at some point a couple of years ago. Now we add the command straight to the EH list, and start with the TMF LUN reset, which ought to implicitly abort the command as well on the target.

usb-storage can do a reset only on the USB device level, which translates to a bus reset on the SCSI level.

And we are supposed to cancel any communication with the device before that.

Regards
Oliver

Benjamin Block

2023-05-03 12:52 UTC #7 lore raw

Quoted 11 lines · Oliver Neukum

Quoted 10 lines · Benjamin Block
On Wed, Apr 26, 2023 at 03:20:07PM -0400, Alan Stern wrote:
From a cursory look at the logs above, SCSI ML does just try that:
Quoted 2 lines
Quoted 2 lines
[  218.089304] sd 0:0:0:0: [sda] tag#0 abort scheduled
[  218.109297] sd 0:0:0:0: [sda] tag#0 aborting command
calls hostt->eh_abort_handler() on the late request, and retries it after success.

Quoted 16 lines

Quoted 4 lines
Quoted 2 lines
Quoted 2 lines
[  218.359964] sd 0:0:0:0: [sda] tag#0 retry aborted command
[  225.129297] sd 0:0:0:0: [sda] tag#0 previous abort failed
but it times out again, then we go straight into EH:
And that is problematic to usb-storage
Quoted 10 lines
Quoted 6 lines
Quoted 6 lines
[  225.129337] scsi host0: Waking error handler thread
[  225.129358] scsi host0: scsi_eh_0: waking up 0/1/1
[  225.129375] scsi host0: scsi_eh_prt_fail_stats: cmds failed: 0, cancel: 1
[  225.129387] scsi host0: Total of 1 commands on 1 devices require eh work
[  225.129402] sd 0:0:0:0: scsi_eh_0: Sending BDR
IIRC in the past we used to call Abort a second time from within the EH thread before trying the different resets, but that was removed at some point a couple of years ago.

Seems like I misremembered. Can't find the commit I was thinking happened, and the only thing that changed was that aborts moved out of the EH thread and be asynchronous.

Quoted 9 lines

Quoted 3 lines
Now we add the command straight to the EH
list, and start with the TMF LUN reset, which ought to implicitly abort the command as well on the target.
usb-storage can do a reset only on the USB device level, which translates to a bus reset on the SCSI level.
And we are supposed to cancel any communication with the device before that.

Is that a limitation of the devices or drivers? Because then you don't match SCSI semantics for LU reset - which aborts all running commands on that scope among things. Which might explain the reason/choice behind this unexpected behavior for you.

On random thought I had: in theory you could implement your own EH strategy handler if the default one doesn't work for you. ATA and SAS do so. [drivers/scsi/scsi_error.c:2285 shost->transportt->eh_strategy_handler()] This can re-use parts/all of the existing escalation sequence in scsi_eh_ready_devs().

But that's no short-term fix.

Signature · 4 lines

Best Regards, Benjamin Block        /        Linux on IBM Z Kernel Development
IBM Deutschland Research & Development GmbH    /   https://www.ibm.com/privacy
Vors. Aufs.-R.: Gregor Pillen         /         Geschäftsführung: David Faller
Sitz der Ges.: Böblingen     /    Registergericht: AmtsG Stuttgart, HRB 243294

Oliver Neukum

2023-05-03 13:55 UTC #8 lore raw

Quoted 8 lines · Benjamin Block

Quoted 5 lines
usb-storage can do a reset only on the USB device level, which translates to a bus reset on the SCSI level.
And we are supposed to cancel any communication with the device before that.
Is that a limitation of the devices or drivers? Because then you don't match SCSI semantics for LU reset - which aborts all running commands

We do not support a LUN reset. That's a limitation of the protocol. If something goes wrong you need to reset the whole USB device, which corresponds to a host adaptor on the SCSI level.

Quoted 2 lines

on that scope among things. Which might explain the reason/choice behind this unexpected behavior for you.

For the device a reset presumably does wipe out the command currently under execution. The problem is within the driver. It thinks that a command is still active. And we are limited to one command at a time (on the whole bus - again protocol limitation)

Quoted 7 lines

On random thought I had: in theory you could implement your own EH strategy handler if the default one doesn't work for you. ATA and SAS do so. [drivers/scsi/scsi_error.c:2285 shost->transportt->eh_strategy_handler()] This can re-use parts/all of the existing escalation sequence in scsi_eh_ready_devs().
But that's no short-term fix.

That looks like using a sledge hammer.

Regards
Oliver

Alan Stern

maintainer

2023-05-03 14:25 UTC #9 lore raw

Quoted 8 lines · Oliver Neukum

Quoted 6 lines · Benjamin Block
Quoted 5 lines
usb-storage can do a reset only on the USB device level, which translates to a bus reset on the SCSI level.
And we are supposed to cancel any communication with the device before that.

Quoted 6 lines

Quoted 2 lines
Is that a limitation of the devices or drivers? Because then you don't match SCSI semantics for LU reset - which aborts all running commands
We do not support a LUN reset. That's a limitation of the protocol. If something goes wrong you need to reset the whole USB device, which corresponds to a host adaptor on the SCSI level.

There is the Bulk-Only Mass Storage Reset request, which is what usb-storage issues when asked to perform a device reset. But few devices implement it correctly.

Quoted 14 lines

Quoted 2 lines
on that scope among things. Which might explain the reason/choice behind this unexpected behavior for you.
For the device a reset presumably does wipe out the command currently under execution. The problem is within the driver. It thinks that a command is still active. And we are limited to one command at a time (on the whole bus - again protocol limitation)
Quoted 6 lines
On random thought I had: in theory you could implement your own EH strategy handler if the default one doesn't work for you. ATA and SAS do so. [drivers/scsi/scsi_error.c:2285 shost->transportt->eh_strategy_handler()] This can re-use parts/all of the existing escalation sequence in scsi_eh_ready_devs().

Quoted 3 lines

Quoted 1 line
But that's no short-term fix.
That looks like using a sledge hammer.

I think the best answer is to accept the patch that started this email thread, perhaps with a minor change. The driver can easily abort the currently running command (if any) on its own before starting a reset.

Alan Stern

Benjamin Block

2023-05-04 08:52 UTC #10 lore raw

Quoted 12 lines · Alan Stern

Quoted 11 lines · Oliver Neukum
For the device a reset presumably does wipe out the command currently under execution. The problem is within the driver. It thinks that a command is still active. And we are limited to one command at a time (on the whole bus - again protocol limitation)
Quoted 6 lines
On random thought I had: in theory you could implement your own EH strategy handler if the default one doesn't work for you. ATA and SAS do so. [drivers/scsi/scsi_error.c:2285 shost->transportt->eh_strategy_handler()] This can re-use parts/all of the existing escalation sequence in scsi_eh_ready_devs().

Quoted 7 lines

Quoted 3 lines
Quoted 1 line
But that's no short-term fix.
That looks like using a sledge hammer.
I think the best answer is to accept the patch that started this email thread, perhaps with a minor change. The driver can easily abort the currently running command (if any) on its own before starting a reset.

I don't think we would add an other layer of aborts in front of device/LUN reset for all SCSI targets. That's just overkill for - it seems - everything but USB storage, and would slow down error recovery considerable in some cases.

If this is supposed to be done in the SCSI ML, it would have to be a quirk/option IMO.

Signature · 4 lines

Best Regards, Benjamin Block        /        Linux on IBM Z Kernel Development
IBM Deutschland Research & Development GmbH    /   https://www.ibm.com/privacy
Vors. Aufs.-R.: Gregor Pillen         /         Geschäftsführung: David Faller
Sitz der Ges.: Böblingen     /    Registergericht: AmtsG Stuttgart, HRB 243294

Alan Stern

maintainer

2023-05-04 14:05 UTC #11 lore raw

Quoted 9 lines · Benjamin Block

Quoted 3 lines · Alan Stern
I think the best answer is to accept the patch that started this email thread, perhaps with a minor change. The driver can easily abort the currently running command (if any) on its own before starting a reset.
I don't think we would add an other layer of aborts in front of device/LUN reset for all SCSI targets. That's just overkill for - it seems - everything but USB storage, and would slow down error recovery considerable in some cases.

This is consistent with what I wrote. The patch that started this email thread made a change to the usb-storage driver; it did not touch any part of the SCSI core.

Maxime, would you like to submit a revised version of your patch? The key difference is that it should abort the currently executing command (if there is one), regardless of whether the srb value matches.

Alan Stern

Quoted 8 lines

If this is supposed to be done in the SCSI ML, it would have to be a quirk/option IMO.

Signature · 4 lines

Best Regards, Benjamin Block        /        Linux on IBM Z Kernel Development
IBM Deutschland Research & Development GmbH    /   https://www.ibm.com/privacy
Vors. Aufs.-R.: Gregor Pillen         /         Geschäftsführung: David Faller
Sitz der Ges.: Böblingen     /    Registergericht: AmtsG Stuttgart, HRB 243294

Maxime Bizon

author

2023-05-04 14:41 UTC #12 lore raw

Quoted 3 lines · Alan Stern

Maxime, would you like to submit a revised version of your patch? The key difference is that it should abort the currently executing command (if there is one), regardless of whether the srb value matches.

Yes

before I do a format submission, is this what you have in mind ?

drivers/usb/storage/scsiglue.c +22 -5

index 8931df5a85fd..380b04273969 100644
@@ -406,10 +406,8 @@ static DEF_SCSI_QCMD(queuecommand)
  ***********************************************************************/
 
 /* Command timeout and abort */
-static int command_abort(struct scsi_cmnd *srb)
+static int command_abort_matching(struct us_data *us, struct scsi_cmnd *srb_match)
 {
-	struct us_data *us = host_to_us(srb->device->host);
-
 	usb_stor_dbg(us, "%s called\n", __func__);
 
 	/*

@@ -418,10 +416,17 @@ static int command_abort(struct scsi_cmnd *srb)
 	 */
 	scsi_lock(us_to_host(us));
 
-	/* Is this command still active? */
-	if (us->srb != srb) {
+	/* is there any active pending command to abort ? */
+	if (!us->srb) {
 		scsi_unlock(us_to_host(us));
 		usb_stor_dbg(us, "-- nothing to abort\n");
+		return SUCCESS;
+	}
+
+	/* Does the command match the passed srb if any ? */
+	if (srb_match && us->srb != srb_match) {
+		scsi_unlock(us_to_host(us));
+		usb_stor_dbg(us, "-- pending command mismatch\n");
 		return FAILED;
 	}

@@ -444,6 +449,16 @@ static int command_abort(struct scsi_cmnd *srb)
 	return SUCCESS;
 }
 
+static int command_abort_any(struct us_data *us)
+{
+	return command_abort_matching(us, NULL);
+}
+
+static int command_abort(struct scsi_cmnd *srb)
+{
+	return command_abort_matching(host_to_us(srb->device->host), srb);
+}
+
 /*
  * This invokes the transport reset mechanism to reset the state of the
  * device

@@ -455,6 +470,8 @@ static int device_reset(struct scsi_cmnd *srb)
 
 	usb_stor_dbg(us, "%s called\n", __func__);
 
+	command_abort_any(us);
+
 	/* lock the device pointers and do the reset */
 	mutex_lock(&(us->dev_mutex));
 	result = us->transport_reset(us);

Signature · 1 line

Maxime

Alan Stern

maintainer

2023-05-04 21:16 UTC #13 lore raw

Quoted 10 lines · Maxime Bizon

Quoted 3 lines · Alan Stern
Maxime, would you like to submit a revised version of your patch? The key difference is that it should abort the currently executing command (if there is one), regardless of whether the srb value matches.
Yes
before I do a format submission, is this what you have in mind ?

Yes, except that I would not make command_abort_any() a separate routine. Just put it inline in device_reset().

Alan Stern

Quoted 67 lines

drivers/usb/storage/scsiglue.c +22 -5

index 8931df5a85fd..380b04273969 100644
@@ -406,10 +406,8 @@ static DEF_SCSI_QCMD(queuecommand)
  ***********************************************************************/
 
 /* Command timeout and abort */
-static int command_abort(struct scsi_cmnd *srb)
+static int command_abort_matching(struct us_data *us, struct scsi_cmnd *srb_match)
 {
-	struct us_data *us = host_to_us(srb->device->host);
-
 	usb_stor_dbg(us, "%s called\n", __func__);
 
 	/*

@@ -418,10 +416,17 @@ static int command_abort(struct scsi_cmnd *srb)
 	 */
 	scsi_lock(us_to_host(us));
 
-	/* Is this command still active? */
-	if (us->srb != srb) {
+	/* is there any active pending command to abort ? */
+	if (!us->srb) {
 		scsi_unlock(us_to_host(us));
 		usb_stor_dbg(us, "-- nothing to abort\n");
+		return SUCCESS;
+	}
+
+	/* Does the command match the passed srb if any ? */
+	if (srb_match && us->srb != srb_match) {
+		scsi_unlock(us_to_host(us));
+		usb_stor_dbg(us, "-- pending command mismatch\n");
 		return FAILED;
 	}

@@ -444,6 +449,16 @@ static int command_abort(struct scsi_cmnd *srb)
 	return SUCCESS;
 }
 
+static int command_abort_any(struct us_data *us)
+{
+	return command_abort_matching(us, NULL);
+}
+
+static int command_abort(struct scsi_cmnd *srb)
+{
+	return command_abort_matching(host_to_us(srb->device->host), srb);
+}
+
 /*
  * This invokes the transport reset mechanism to reset the state of the
  * device

@@ -455,6 +470,8 @@ static int device_reset(struct scsi_cmnd *srb)
 
 	usb_stor_dbg(us, "%s called\n", __func__);
 
+	command_abort_any(us);
+
 	/* lock the device pointers and do the reset */
 	mutex_lock(&(us->dev_mutex));
 	result = us->transport_reset(us);

Signature · 2 lines

-- 
Maxime