[PATCH 0/1] scsi: core: Restart a stopped queue when sysfs sets a device running

[Brian Bunker <brian@purestorage.com>]

A SCSI device can be left in SDEV_RUNNING with its request queue stopped
for good. The task that put it there hangs holding the device lock, and
anything else that takes the lock hangs behind it.

This was seen with iSCSI when a session drops again just after
recovering. The error handler offlines a device while its transport has
it blocked, which leaves the queue stopped. iscsid then writes "running"
to the device's state attribute and store_state_field() moves it to
SDEV_RUNNING without restarting the queue. The rescan it starts sends an
INQUIRY that can never be dispatched. When the transport later unblocks
the device, scsi_internal_device_unblock_nowait() skips it because it is
already running, so nothing restarts the queue.

Evidence from a vmcore of a hung initiator (a RHEL 9.6 5.14 kernel; the
code involved is the same in mainline). The device is sd 0:0:0:1, and
iscsid is the task that wrote "running" to it:

  PID: 12087  TASK: ffff9635c9c80000  COMMAND: "iscsid"
   #5 blk_execute_rq
   #6 scsi_execute_cmd
   #7 scsi_vpd_inquiry
  #10 scsi_attach_vpd
  #11 scsi_rescan_device_rh
  #12 store_state_field
  #13 kernfs_fop_write_iter

  sdev_state                   = SDEV_RUNNING
  queue_stopped                = 1
  request_queue->quiesce_depth = 1
  sdev_gendev.mutex.owner      = 0xffff9635c9c80001 (iscsid, plus a flag bit)

The INQUIRY iscsid is waiting on belongs to that device's queue and was
never dispatched:

  state = MQ_RQ_IDLE, start_time_ns = 0, deadline = 0

The other LUNs of the same session were unblocked by the transport and
had their queues restarted:

  lun 1: SDEV_RUNNING            queue_stopped = 1
  lun 2: SDEV_TRANSPORT_OFFLINE  queue_stopped = 0
  ...
  lun 9: SDEV_TRANSPORT_OFFLINE  queue_stopped = 0

(scsi_rescan_device_rh is this distro kernel's name for
scsi_rescan_device().)

The kernel log of the same crash shows the sequence for the stuck device
(sd 0:0:0:1) and its siblings:

  [50958.843822]  connection9:0: detected conn error (1021)
  [50968.259428]  connection9:0: detected conn error (1020)
  [50968.259456] sd 0:0:0:1: Device offlined - not ready after error recovery
  [50978.298947]  session9: session recovery timed out after 10 secs
  [50978.298977] sd 0:0:0:2: rejecting I/O to offline device

The other LUNs are unblocked by the recovery timeout at 50978. The
offlined device is not: by then it had already been written back to
running.

Only a device that the error handler offlined while it was blocked can
end up like this. A device that the transport unblocks normally has its
queue restarted, and sysfs only accepts "running" for a device that is
running or offline.

So in the case above, the error handler offlined the device, iscsid
wrote "running" to it, and only then did the recovery timeout unblock
the session. All three happened within about ten seconds, which is why
this is rare.

The fix restarts the queue in store_state_field() when it moves a device
to SDEV_RUNNING. scsi_start_queue() is a no-op when the queue is not
stopped, so this is harmless for devices that were never blocked.

I do not have a deterministic reproducer. The analysis above comes from
the vmcore, and initiators running with this patch have not hit the hang
again, but with a race this narrow that is not proof the patch fixes it.
Review of the state transitions is welcome.

Brian Bunker (1):
  scsi: core: Restart a stopped queue when sysfs sets a device running

 drivers/scsi/scsi_sysfs.c | 10 +++++++++-
 1 file changed, 9 insertions(+), 1 deletion(-)

-- 
2.56.0