[PATCH 0/2] scsi command timeout fixes

[PATCH 0/2] scsi command timeout fixes

[Hannes Reinecke]

Hi all,

I've received reports claiming they're seeing a double command completion
occasionally when a command timeout happens.

Delving into it I found this this indeed might happening; reason being
that the LLDD will only be informed about a timed-out command by
calling scsi_try_to_abort_command(). Anytime before that the LLDD
is free to assume the command is valid and might call scsi_done() on it.
Which then will lead to interesting issues in the error handler.

And while debugging this I've found we're setting DID_TIME_OUT incorrectly,
which might lead to spurious command timeout detection.

Hannes Reinecke (2):
  scsi_error: set DID_TIME_OUT correctly
  scsi: Do not complete timed-out command

 drivers/scsi/scsi.c       |  2 ++
 drivers/scsi/scsi_error.c | 16 +++++++++-------
 drivers/scsi/scsi_priv.h  |  1 +
 3 files changed, 12 insertions(+), 7 deletions(-)

-- 
1.7.12.4

[PATCH 1/2] scsi_error: set DID_TIME_OUT correctly

[Hannes Reinecke]

Any callbacks in scsi_timeout_out() might return BLK_EH_RESET_TIMER,
in which case we should leave the result alone and not set
DID_TIME_OUT, as the command didn't actually timeout.

Signed-off-by: Hannes Reinecke <hare@suse.de>
---
 drivers/scsi/scsi_error.c | 10 +++++-----
 1 file changed, 5 insertions(+), 5 deletions(-)

diff --git a/drivers/scsi/scsi_error.c b/drivers/scsi/scsi_error.c
index 47a1ffc..ff176a6 100644
--- a/drivers/scsi/scsi_error.c
+++ b/drivers/scsi/scsi_error.c
@@ -291,11 +291,11 @@ enum blk_eh_timer_return scsi_times_out(struct request *req)
 		if (scsi_abort_command(scmd) == SUCCESS)
 			return BLK_EH_NOT_HANDLED;
 
-	scmd->result |= DID_TIME_OUT << 16;
-
-	if (unlikely(rtn == BLK_EH_NOT_HANDLED &&
-		     !scsi_eh_scmd_add(scmd, SCSI_EH_CANCEL_CMD)))
-		rtn = BLK_EH_HANDLED;
+	if (unlikely(rtn == BLK_EH_NOT_HANDLED)) {
+		scmd->result |= DID_TIME_OUT << 16;
+		if (!scsi_eh_scmd_add(scmd, SCSI_EH_CANCEL_CMD))
+			rtn = BLK_EH_HANDLED;
+	}
 
 	return rtn;
 }
-- 
1.7.12.4

Re: [PATCH 1/2] scsi_error: set DID_TIME_OUT correctly

[Ewan Milne]

On Fri, 2014-06-13 at 14:01 +0200, Hannes Reinecke wrote:
> Any callbacks in scsi_timeout_out() might return BLK_EH_RESET_TIMER,
> in which case we should leave the result alone and not set
> DID_TIME_OUT, as the command didn't actually timeout.
> 
> Signed-off-by: Hannes Reinecke <hare@suse.de>
> ---
>  drivers/scsi/scsi_error.c | 10 +++++-----
>  1 file changed, 5 insertions(+), 5 deletions(-)
> 
> diff --git a/drivers/scsi/scsi_error.c b/drivers/scsi/scsi_error.c
> index 47a1ffc..ff176a6 100644
> --- a/drivers/scsi/scsi_error.c
> +++ b/drivers/scsi/scsi_error.c
> @@ -291,11 +291,11 @@ enum blk_eh_timer_return scsi_times_out(struct request *req)
>  		if (scsi_abort_command(scmd) == SUCCESS)
>  			return BLK_EH_NOT_HANDLED;
>  
> -	scmd->result |= DID_TIME_OUT << 16;
> -
> -	if (unlikely(rtn == BLK_EH_NOT_HANDLED &&
> -		     !scsi_eh_scmd_add(scmd, SCSI_EH_CANCEL_CMD)))
> -		rtn = BLK_EH_HANDLED;
> +	if (unlikely(rtn == BLK_EH_NOT_HANDLED)) {
> +		scmd->result |= DID_TIME_OUT << 16;
> +		if (!scsi_eh_scmd_add(scmd, SCSI_EH_CANCEL_CMD))
> +			rtn = BLK_EH_HANDLED;
> +	}
>  
>  	return rtn;
>  }

See Paolo's patch series which includes:

[PATCH v3 4/6] scsi_error: fix invalid setting of host byte

I think your patch won't apply after his.

-Ewan

Re: [PATCH 1/2] scsi_error: set DID_TIME_OUT correctly

[Christoph Hellwig]

On Fri, Jun 13, 2014 at 10:32:14AM -0400, Ewan Milne wrote:
> See Paolo's patch series which includes:
> 
> [PATCH v3 4/6] scsi_error: fix invalid setting of host byte
> 
> I think your patch won't apply after his.

Might make sense to rebase this, which shouldn't be too hard.

I already have a local tree with the few remaining for 3.16 fixes, but
James didn't reply if he actually agrees with them so far.

[PATCH 2/2] scsi: Do not complete timed-out command

[Hannes Reinecke]

There is a possible race between scsi_times_out() and scsi_done();
the LLDD is only notified about a timed out command by calling
scsi_try_to_abort_command(). Anytime before that the LLDD is
free to complete the command via scsi_done().
By this time, however, the command might've been timed-out already,
leaving us with a stale command in the error handler.
Fix this by separating out the two meanings of the
SCSI_EH_ABORT_SCHEDULED flag; it's used to signal that
a) the asynchronous abort has been schedule
and
b) that an asynchronous abourt had been running, the command
   has been retried, and has timed out again.

This patch implements a new flag SCSI_EH_CMD_TIMEOUT to signal
that a command has run into a timeout (and thus can be used
to detect case b) above). The existing flag
SCSI_EH_CMD_ABORT_SCHEDULED is now restricted to signal
'the asynchronous abort has been scheduled', and thus should be
checked in scsi_done() to avoid the mentioned race.

Signed-off-by: Hannes Reinecke <hare@suse.de>
---
 drivers/scsi/scsi.c       | 2 ++
 drivers/scsi/scsi_error.c | 6 ++++--
 drivers/scsi/scsi_priv.h  | 1 +
 3 files changed, 7 insertions(+), 2 deletions(-)

diff --git a/drivers/scsi/scsi.c b/drivers/scsi/scsi.c
index 88d46fe..7a58fbe 100644
--- a/drivers/scsi/scsi.c
+++ b/drivers/scsi/scsi.c
@@ -739,6 +739,8 @@ int scsi_dispatch_cmd(struct scsi_cmnd *cmd)
  */
 static void scsi_done(struct scsi_cmnd *cmd)
 {
+	if (WARN_ON_ONCE(cmd->eh_eflags & SCSI_EH_ABORT_SCHEDULED))
+		return;
 	trace_scsi_dispatch_cmd_done(cmd);
 	blk_complete_request(cmd->request);
 }
diff --git a/drivers/scsi/scsi_error.c b/drivers/scsi/scsi_error.c
index ff176a6..cde9c11 100644
--- a/drivers/scsi/scsi_error.c
+++ b/drivers/scsi/scsi_error.c
@@ -125,11 +125,13 @@ scmd_eh_abort_handler(struct work_struct *work)
 			scmd_printk(KERN_INFO, scmd,
 				    "scmd %p eh timeout, not aborting\n",
 				    scmd));
+		scmd->eh_eflags &= ~SCSI_EH_ABORT_SCHEDULED;
 	} else {
 		SCSI_LOG_ERROR_RECOVERY(3,
 			scmd_printk(KERN_INFO, scmd,
 				    "aborting command %p\n", scmd));
 		rtn = scsi_try_to_abort_cmd(sdev->host->hostt, scmd);
+		scmd->eh_eflags &= ~SCSI_EH_ABORT_SCHEDULED;
 		if (rtn == SUCCESS) {
 			scmd->result |= DID_TIME_OUT << 16;
 			if (scsi_host_eh_past_deadline(sdev->host)) {
@@ -185,17 +187,17 @@ scsi_abort_command(struct scsi_cmnd *scmd)
 	struct Scsi_Host *shost = sdev->host;
 	unsigned long flags;
 
-	if (scmd->eh_eflags & SCSI_EH_ABORT_SCHEDULED) {
+	if (scmd->eh_eflags & SCSI_EH_CMD_TIMEOUT) {
 		/*
 		 * Retry after abort failed, escalate to next level.
 		 */
-		scmd->eh_eflags &= ~SCSI_EH_ABORT_SCHEDULED;
 		SCSI_LOG_ERROR_RECOVERY(3,
 			scmd_printk(KERN_INFO, scmd,
 				    "scmd %p previous abort failed\n", scmd));
 		cancel_delayed_work(&scmd->abort_work);
 		return FAILED;
 	}
+	scmd->eh_eflags |= SCSI_EH_CMD_TIMEOUT;
 
 	/*
 	 * Do not try a command abort if
diff --git a/drivers/scsi/scsi_priv.h b/drivers/scsi/scsi_priv.h
index 48e5b65..66b387d 100644
--- a/drivers/scsi/scsi_priv.h
+++ b/drivers/scsi/scsi_priv.h
@@ -20,6 +20,7 @@ struct scsi_nl_hdr;
  */
 #define SCSI_EH_CANCEL_CMD	0x0001	/* Cancel this cmd */
 #define SCSI_EH_ABORT_SCHEDULED	0x0002	/* Abort has been scheduled */
+#define SCSI_EH_CMD_TIMEOUT	0x0004	/* Command has timed out */
 
 #define SCSI_SENSE_VALID(scmd) \
 	(((scmd)->sense_buffer[0] & 0x70) == 0x70)
-- 
1.7.12.4

Re: [PATCH 2/2] scsi: Do not complete timed-out command

[Christoph Hellwig]

> diff --git a/drivers/scsi/scsi_error.c b/drivers/scsi/scsi_error.c
> index ff176a6..cde9c11 100644
> --- a/drivers/scsi/scsi_error.c
> +++ b/drivers/scsi/scsi_error.c
> @@ -125,11 +125,13 @@ scmd_eh_abort_handler(struct work_struct *work)
>  			scmd_printk(KERN_INFO, scmd,
>  				    "scmd %p eh timeout, not aborting\n",
>  				    scmd));
> +		scmd->eh_eflags &= ~SCSI_EH_ABORT_SCHEDULED;

What lock is supposed to prevent concurrent modifications to eh_eflags
here?

Re: [PATCH 2/2] scsi: Do not complete timed-out command

[Ewan Milne]

On Fri, 2014-06-13 at 14:01 +0200, Hannes Reinecke wrote:
> There is a possible race between scsi_times_out() and scsi_done();
> the LLDD is only notified about a timed out command by calling
> scsi_try_to_abort_command(). Anytime before that the LLDD is
> free to complete the command via scsi_done().
> By this time, however, the command might've been timed-out already,
> leaving us with a stale command in the error handler.
> Fix this by separating out the two meanings of the
> SCSI_EH_ABORT_SCHEDULED flag; it's used to signal that
> a) the asynchronous abort has been schedule
> and
> b) that an asynchronous abourt had been running, the command
>    has been retried, and has timed out again.
> 
> This patch implements a new flag SCSI_EH_CMD_TIMEOUT to signal
> that a command has run into a timeout (and thus can be used
> to detect case b) above). The existing flag
> SCSI_EH_CMD_ABORT_SCHEDULED is now restricted to signal
> 'the asynchronous abort has been scheduled', and thus should be
> checked in scsi_done() to avoid the mentioned race.
> 
> Signed-off-by: Hannes Reinecke <hare@suse.de>
> ---
>  drivers/scsi/scsi.c       | 2 ++
>  drivers/scsi/scsi_error.c | 6 ++++--
>  drivers/scsi/scsi_priv.h  | 1 +
>  3 files changed, 7 insertions(+), 2 deletions(-)
> 
> diff --git a/drivers/scsi/scsi.c b/drivers/scsi/scsi.c
> index 88d46fe..7a58fbe 100644
> --- a/drivers/scsi/scsi.c
> +++ b/drivers/scsi/scsi.c
> @@ -739,6 +739,8 @@ int scsi_dispatch_cmd(struct scsi_cmnd *cmd)
>   */
>  static void scsi_done(struct scsi_cmnd *cmd)
>  {
> +	if (WARN_ON_ONCE(cmd->eh_eflags & SCSI_EH_ABORT_SCHEDULED))
> +		return;
>  	trace_scsi_dispatch_cmd_done(cmd);
>  	blk_complete_request(cmd->request);
>  }
> diff --git a/drivers/scsi/scsi_error.c b/drivers/scsi/scsi_error.c
> index ff176a6..cde9c11 100644
> --- a/drivers/scsi/scsi_error.c
> +++ b/drivers/scsi/scsi_error.c
> @@ -125,11 +125,13 @@ scmd_eh_abort_handler(struct work_struct *work)
>  			scmd_printk(KERN_INFO, scmd,
>  				    "scmd %p eh timeout, not aborting\n",
>  				    scmd));
> +		scmd->eh_eflags &= ~SCSI_EH_ABORT_SCHEDULED;
>  	} else {
>  		SCSI_LOG_ERROR_RECOVERY(3,
>  			scmd_printk(KERN_INFO, scmd,
>  				    "aborting command %p\n", scmd));
>  		rtn = scsi_try_to_abort_cmd(sdev->host->hostt, scmd);
> +		scmd->eh_eflags &= ~SCSI_EH_ABORT_SCHEDULED;
>  		if (rtn == SUCCESS) {
>  			scmd->result |= DID_TIME_OUT << 16;
>  			if (scsi_host_eh_past_deadline(sdev->host)) {
> @@ -185,17 +187,17 @@ scsi_abort_command(struct scsi_cmnd *scmd)
>  	struct Scsi_Host *shost = sdev->host;
>  	unsigned long flags;
>  
> -	if (scmd->eh_eflags & SCSI_EH_ABORT_SCHEDULED) {
> +	if (scmd->eh_eflags & SCSI_EH_CMD_TIMEOUT) {
>  		/*
>  		 * Retry after abort failed, escalate to next level.
>  		 */
> -		scmd->eh_eflags &= ~SCSI_EH_ABORT_SCHEDULED;
>  		SCSI_LOG_ERROR_RECOVERY(3,
>  			scmd_printk(KERN_INFO, scmd,
>  				    "scmd %p previous abort failed\n", scmd));
>  		cancel_delayed_work(&scmd->abort_work);
>  		return FAILED;
>  	}
> +	scmd->eh_eflags |= SCSI_EH_CMD_TIMEOUT;
>  
>  	/*
>  	 * Do not try a command abort if
> diff --git a/drivers/scsi/scsi_priv.h b/drivers/scsi/scsi_priv.h
> index 48e5b65..66b387d 100644
> --- a/drivers/scsi/scsi_priv.h
> +++ b/drivers/scsi/scsi_priv.h
> @@ -20,6 +20,7 @@ struct scsi_nl_hdr;
>   */
>  #define SCSI_EH_CANCEL_CMD	0x0001	/* Cancel this cmd */
>  #define SCSI_EH_ABORT_SCHEDULED	0x0002	/* Abort has been scheduled */
> +#define SCSI_EH_CMD_TIMEOUT	0x0004	/* Command has timed out */
>  
>  #define SCSI_SENSE_VALID(scmd) \
>  	(((scmd)->sense_buffer[0] & 0x70) == 0x70)

So, let me see if I follow the logic here...

This patch changes the meaning of the SCSI_EH_ABORT_SCHEDULED flag
so that this flag is set during the time the queue_delayed_work() item
is pending, until the LLD returns from the ->eh_abort_handler() call.
It also adds a new flag SCSI_EH_CMD_TIMEOUT which is set (essentially)
when the scmd has timed out, and prevent scsi_abort_command() from
doing anything more than once (until scmd->eh_eflags is reset).

I don't quite get why scsi_eh_scmd_add() tests SCSI_EH_ABORT_SCHEDULED:

>        if (shost->eh_deadline != -1 && !shost->last_reset)
>                shost->last_reset = jiffies;
>
>        ret = 1;
>        if (scmd->eh_eflags & SCSI_EH_ABORT_SCHEDULED)
>                eh_flag &= ~SCSI_EH_CANCEL_CMD;
>        scmd->eh_eflags |= eh_flag;
>        list_add_tail(&scmd->eh_entry, &shost->eh_cmd_q);
>        shost->host_failed++;
>        scsi_eh_wakeup(shost);

...since it seems like that flag wouldn't still be set by the time we
get to the point where we are adding the scmd to the eh_cmd_q list.

I'm also not sure why this case in scsi_decide_disposition():

>        case DID_ABORT:
>                if (scmd->eh_eflags & SCSI_EH_ABORT_SCHEDULED) {
>                        scmd->result |= DID_TIME_OUT << 16;
>                        return SUCCESS;
>                }

...is looking at SCSI_EH_ABORT_SCHEDULED, for similar reasons.

The WARN_ON_ONCE() case in scsi_done():

>static void scsi_done(struct scsi_cmnd *cmd)
>{
>        if (WARN_ON_ONCE(cmd->eh_eflags & SCSI_EH_ABORT_SCHEDULED))
>                return;
>        trace_scsi_dispatch_cmd_done(cmd);
>        blk_complete_request(cmd->request);
>}

...seems like it should never go off because of the REQ_ATOM_COMPLETE
logic in the block layer, assuming that logic is working.

Can you verify this is the intended behavior, or perhaps explain
what hole this patch is attempting to plug?  It seems like it is
dealing with the case of scsi_done() being called after a timeout
but before the delayed_work abort mechanism runs.  Is this actually
what is happening?

Reviewed-by: Ewan D. Milne <emilne@redhat.com>

Re: [PATCH 2/2] scsi: Do not complete timed-out command

[Hannes Reinecke]

On 06/16/2014 08:23 PM, Ewan Milne wrote:
> On Fri, 2014-06-13 at 14:01 +0200, Hannes Reinecke wrote:
>> There is a possible race between scsi_times_out() and scsi_done();
>> the LLDD is only notified about a timed out command by calling
>> scsi_try_to_abort_command(). Anytime before that the LLDD is
>> free to complete the command via scsi_done().
>> By this time, however, the command might've been timed-out already,
>> leaving us with a stale command in the error handler.
>> Fix this by separating out the two meanings of the
>> SCSI_EH_ABORT_SCHEDULED flag; it's used to signal that
>> a) the asynchronous abort has been schedule
>> and
>> b) that an asynchronous abourt had been running, the command
>>     has been retried, and has timed out again.
>>
>> This patch implements a new flag SCSI_EH_CMD_TIMEOUT to signal
>> that a command has run into a timeout (and thus can be used
>> to detect case b) above). The existing flag
>> SCSI_EH_CMD_ABORT_SCHEDULED is now restricted to signal
>> 'the asynchronous abort has been scheduled', and thus should be
>> checked in scsi_done() to avoid the mentioned race.
>>
>> Signed-off-by: Hannes Reinecke <hare@suse.de>
>> ---
>>   drivers/scsi/scsi.c       | 2 ++
>>   drivers/scsi/scsi_error.c | 6 ++++--
>>   drivers/scsi/scsi_priv.h  | 1 +
>>   3 files changed, 7 insertions(+), 2 deletions(-)
>>
>> diff --git a/drivers/scsi/scsi.c b/drivers/scsi/scsi.c
>> index 88d46fe..7a58fbe 100644
>> --- a/drivers/scsi/scsi.c
>> +++ b/drivers/scsi/scsi.c
>> @@ -739,6 +739,8 @@ int scsi_dispatch_cmd(struct scsi_cmnd *cmd)
>>    */
>>   static void scsi_done(struct scsi_cmnd *cmd)
>>   {
>> +	if (WARN_ON_ONCE(cmd->eh_eflags & SCSI_EH_ABORT_SCHEDULED))
>> +		return;
>>   	trace_scsi_dispatch_cmd_done(cmd);
>>   	blk_complete_request(cmd->request);
>>   }
>> diff --git a/drivers/scsi/scsi_error.c b/drivers/scsi/scsi_error.c
>> index ff176a6..cde9c11 100644
>> --- a/drivers/scsi/scsi_error.c
>> +++ b/drivers/scsi/scsi_error.c
>> @@ -125,11 +125,13 @@ scmd_eh_abort_handler(struct work_struct *work)
>>   			scmd_printk(KERN_INFO, scmd,
>>   				    "scmd %p eh timeout, not aborting\n",
>>   				    scmd));
>> +		scmd->eh_eflags &= ~SCSI_EH_ABORT_SCHEDULED;
>>   	} else {
>>   		SCSI_LOG_ERROR_RECOVERY(3,
>>   			scmd_printk(KERN_INFO, scmd,
>>   				    "aborting command %p\n", scmd));
>>   		rtn = scsi_try_to_abort_cmd(sdev->host->hostt, scmd);
>> +		scmd->eh_eflags &= ~SCSI_EH_ABORT_SCHEDULED;
>>   		if (rtn == SUCCESS) {
>>   			scmd->result |= DID_TIME_OUT << 16;
>>   			if (scsi_host_eh_past_deadline(sdev->host)) {
>> @@ -185,17 +187,17 @@ scsi_abort_command(struct scsi_cmnd *scmd)
>>   	struct Scsi_Host *shost = sdev->host;
>>   	unsigned long flags;
>>
>> -	if (scmd->eh_eflags & SCSI_EH_ABORT_SCHEDULED) {
>> +	if (scmd->eh_eflags & SCSI_EH_CMD_TIMEOUT) {
>>   		/*
>>   		 * Retry after abort failed, escalate to next level.
>>   		 */
>> -		scmd->eh_eflags &= ~SCSI_EH_ABORT_SCHEDULED;
>>   		SCSI_LOG_ERROR_RECOVERY(3,
>>   			scmd_printk(KERN_INFO, scmd,
>>   				    "scmd %p previous abort failed\n", scmd));
>>   		cancel_delayed_work(&scmd->abort_work);
>>   		return FAILED;
>>   	}
>> +	scmd->eh_eflags |= SCSI_EH_CMD_TIMEOUT;
>>
>>   	/*
>>   	 * Do not try a command abort if
>> diff --git a/drivers/scsi/scsi_priv.h b/drivers/scsi/scsi_priv.h
>> index 48e5b65..66b387d 100644
>> --- a/drivers/scsi/scsi_priv.h
>> +++ b/drivers/scsi/scsi_priv.h
>> @@ -20,6 +20,7 @@ struct scsi_nl_hdr;
>>    */
>>   #define SCSI_EH_CANCEL_CMD	0x0001	/* Cancel this cmd */
>>   #define SCSI_EH_ABORT_SCHEDULED	0x0002	/* Abort has been scheduled */
>> +#define SCSI_EH_CMD_TIMEOUT	0x0004	/* Command has timed out */
>>
>>   #define SCSI_SENSE_VALID(scmd) \
>>   	(((scmd)->sense_buffer[0] & 0x70) == 0x70)
>
> So, let me see if I follow the logic here...
>
> This patch changes the meaning of the SCSI_EH_ABORT_SCHEDULED flag
> so that this flag is set during the time the queue_delayed_work() item
> is pending, until the LLD returns from the ->eh_abort_handler() call.
> It also adds a new flag SCSI_EH_CMD_TIMEOUT which is set (essentially)
> when the scmd has timed out, and prevent scsi_abort_command() from
> doing anything more than once (until scmd->eh_eflags is reset).
>
> I don't quite get why scsi_eh_scmd_add() tests SCSI_EH_ABORT_SCHEDULED:
>
>>         if (shost->eh_deadline != -1 && !shost->last_reset)
>>                 shost->last_reset = jiffies;
>>
>>         ret = 1;
>>         if (scmd->eh_eflags & SCSI_EH_ABORT_SCHEDULED)
>>                 eh_flag &= ~SCSI_EH_CANCEL_CMD;
>>         scmd->eh_eflags |= eh_flag;
>>         list_add_tail(&scmd->eh_entry, &shost->eh_cmd_q);
>>         shost->host_failed++;
>>         scsi_eh_wakeup(shost);
>
> ...since it seems like that flag wouldn't still be set by the time we
> get to the point where we are adding the scmd to the eh_cmd_q list.
>
> I'm also not sure why this case in scsi_decide_disposition():
>
>>         case DID_ABORT:
>>                 if (scmd->eh_eflags & SCSI_EH_ABORT_SCHEDULED) {
>>                         scmd->result |= DID_TIME_OUT << 16;
>>                         return SUCCESS;
>>                 }
>
> ...is looking at SCSI_EH_ABORT_SCHEDULED, for similar reasons.
>
> The WARN_ON_ONCE() case in scsi_done():
>
>> static void scsi_done(struct scsi_cmnd *cmd)
>> {
>>         if (WARN_ON_ONCE(cmd->eh_eflags & SCSI_EH_ABORT_SCHEDULED))
>>                 return;
>>         trace_scsi_dispatch_cmd_done(cmd);
>>         blk_complete_request(cmd->request);
>> }
>
> ...seems like it should never go off because of the REQ_ATOM_COMPLETE
> logic in the block layer, assuming that logic is working.
>
> Can you verify this is the intended behavior, or perhaps explain
> what hole this patch is attempting to plug?  It seems like it is
> dealing with the case of scsi_done() being called after a timeout
> but before the delayed_work abort mechanism runs.  Is this actually
> what is happening?
>
> Reviewed-by: Ewan D. Milne <emilne@redhat.com>
>
After the explanation from James B. it might indeed be handled by 
REQ_ATOM_COMPLETE, and the real reason were the missing USB fixes.
I've sent a test kernel with the USB fixes to our customer and wait
for feedback there.

I'll be retracting this patchset for the time being.

Cheers,

Hannes
-- 
Dr. Hannes Reinecke		      zSeries & Storage
hare@suse.de			      +49 911 74053 688
SUSE LINUX Products GmbH, Maxfeldstr. 5, 90409 Nürnberg
GF: J. Hawn, J. Guild, F. Imendörffer, HRB 16746 (AG Nürnberg)
--
To unsubscribe from this list: send the line "unsubscribe linux-scsi" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [PATCH 2/2] scsi: Do not complete timed-out command

[Ewan Milne]

On Tue, 2014-06-17 at 07:53 +0200, Hannes Reinecke wrote:
> On 06/16/2014 08:23 PM, Ewan Milne wrote:
> > On Fri, 2014-06-13 at 14:01 +0200, Hannes Reinecke wrote:
> >> There is a possible race between scsi_times_out() and scsi_done();
> >> the LLDD is only notified about a timed out command by calling
> >> scsi_try_to_abort_command(). Anytime before that the LLDD is
> >> free to complete the command via scsi_done().
> >> By this time, however, the command might've been timed-out already,
> >> leaving us with a stale command in the error handler.
> >> Fix this by separating out the two meanings of the
> >> SCSI_EH_ABORT_SCHEDULED flag; it's used to signal that
> >> a) the asynchronous abort has been schedule
> >> and
> >> b) that an asynchronous abourt had been running, the command
> >>     has been retried, and has timed out again.
> >>
> >> This patch implements a new flag SCSI_EH_CMD_TIMEOUT to signal
> >> that a command has run into a timeout (and thus can be used
> >> to detect case b) above). The existing flag
> >> SCSI_EH_CMD_ABORT_SCHEDULED is now restricted to signal
> >> 'the asynchronous abort has been scheduled', and thus should be
> >> checked in scsi_done() to avoid the mentioned race.
> >>
> >> Signed-off-by: Hannes Reinecke <hare@suse.de>
> >> ---
> >>   drivers/scsi/scsi.c       | 2 ++
> >>   drivers/scsi/scsi_error.c | 6 ++++--
> >>   drivers/scsi/scsi_priv.h  | 1 +
> >>   3 files changed, 7 insertions(+), 2 deletions(-)
> >>
> >> diff --git a/drivers/scsi/scsi.c b/drivers/scsi/scsi.c
> >> index 88d46fe..7a58fbe 100644
> >> --- a/drivers/scsi/scsi.c
> >> +++ b/drivers/scsi/scsi.c
> >> @@ -739,6 +739,8 @@ int scsi_dispatch_cmd(struct scsi_cmnd *cmd)
> >>    */
> >>   static void scsi_done(struct scsi_cmnd *cmd)
> >>   {
> >> +	if (WARN_ON_ONCE(cmd->eh_eflags & SCSI_EH_ABORT_SCHEDULED))
> >> +		return;
> >>   	trace_scsi_dispatch_cmd_done(cmd);
> >>   	blk_complete_request(cmd->request);
> >>   }
> >> diff --git a/drivers/scsi/scsi_error.c b/drivers/scsi/scsi_error.c
> >> index ff176a6..cde9c11 100644
> >> --- a/drivers/scsi/scsi_error.c
> >> +++ b/drivers/scsi/scsi_error.c
> >> @@ -125,11 +125,13 @@ scmd_eh_abort_handler(struct work_struct *work)
> >>   			scmd_printk(KERN_INFO, scmd,
> >>   				    "scmd %p eh timeout, not aborting\n",
> >>   				    scmd));
> >> +		scmd->eh_eflags &= ~SCSI_EH_ABORT_SCHEDULED;
> >>   	} else {
> >>   		SCSI_LOG_ERROR_RECOVERY(3,
> >>   			scmd_printk(KERN_INFO, scmd,
> >>   				    "aborting command %p\n", scmd));
> >>   		rtn = scsi_try_to_abort_cmd(sdev->host->hostt, scmd);
> >> +		scmd->eh_eflags &= ~SCSI_EH_ABORT_SCHEDULED;
> >>   		if (rtn == SUCCESS) {
> >>   			scmd->result |= DID_TIME_OUT << 16;
> >>   			if (scsi_host_eh_past_deadline(sdev->host)) {
> >> @@ -185,17 +187,17 @@ scsi_abort_command(struct scsi_cmnd *scmd)
> >>   	struct Scsi_Host *shost = sdev->host;
> >>   	unsigned long flags;
> >>
> >> -	if (scmd->eh_eflags & SCSI_EH_ABORT_SCHEDULED) {
> >> +	if (scmd->eh_eflags & SCSI_EH_CMD_TIMEOUT) {
> >>   		/*
> >>   		 * Retry after abort failed, escalate to next level.
> >>   		 */
> >> -		scmd->eh_eflags &= ~SCSI_EH_ABORT_SCHEDULED;
> >>   		SCSI_LOG_ERROR_RECOVERY(3,
> >>   			scmd_printk(KERN_INFO, scmd,
> >>   				    "scmd %p previous abort failed\n", scmd));
> >>   		cancel_delayed_work(&scmd->abort_work);
> >>   		return FAILED;
> >>   	}
> >> +	scmd->eh_eflags |= SCSI_EH_CMD_TIMEOUT;
> >>
> >>   	/*
> >>   	 * Do not try a command abort if
> >> diff --git a/drivers/scsi/scsi_priv.h b/drivers/scsi/scsi_priv.h
> >> index 48e5b65..66b387d 100644
> >> --- a/drivers/scsi/scsi_priv.h
> >> +++ b/drivers/scsi/scsi_priv.h
> >> @@ -20,6 +20,7 @@ struct scsi_nl_hdr;
> >>    */
> >>   #define SCSI_EH_CANCEL_CMD	0x0001	/* Cancel this cmd */
> >>   #define SCSI_EH_ABORT_SCHEDULED	0x0002	/* Abort has been scheduled */
> >> +#define SCSI_EH_CMD_TIMEOUT	0x0004	/* Command has timed out */
> >>
> >>   #define SCSI_SENSE_VALID(scmd) \
> >>   	(((scmd)->sense_buffer[0] & 0x70) == 0x70)
> >
> > So, let me see if I follow the logic here...
> >
> > This patch changes the meaning of the SCSI_EH_ABORT_SCHEDULED flag
> > so that this flag is set during the time the queue_delayed_work() item
> > is pending, until the LLD returns from the ->eh_abort_handler() call.
> > It also adds a new flag SCSI_EH_CMD_TIMEOUT which is set (essentially)
> > when the scmd has timed out, and prevent scsi_abort_command() from
> > doing anything more than once (until scmd->eh_eflags is reset).
> >
> > I don't quite get why scsi_eh_scmd_add() tests SCSI_EH_ABORT_SCHEDULED:
> >
> >>         if (shost->eh_deadline != -1 && !shost->last_reset)
> >>                 shost->last_reset = jiffies;
> >>
> >>         ret = 1;
> >>         if (scmd->eh_eflags & SCSI_EH_ABORT_SCHEDULED)
> >>                 eh_flag &= ~SCSI_EH_CANCEL_CMD;
> >>         scmd->eh_eflags |= eh_flag;
> >>         list_add_tail(&scmd->eh_entry, &shost->eh_cmd_q);
> >>         shost->host_failed++;
> >>         scsi_eh_wakeup(shost);
> >
> > ...since it seems like that flag wouldn't still be set by the time we
> > get to the point where we are adding the scmd to the eh_cmd_q list.
> >
> > I'm also not sure why this case in scsi_decide_disposition():
> >
> >>         case DID_ABORT:
> >>                 if (scmd->eh_eflags & SCSI_EH_ABORT_SCHEDULED) {
> >>                         scmd->result |= DID_TIME_OUT << 16;
> >>                         return SUCCESS;
> >>                 }
> >
> > ...is looking at SCSI_EH_ABORT_SCHEDULED, for similar reasons.
> >
> > The WARN_ON_ONCE() case in scsi_done():
> >
> >> static void scsi_done(struct scsi_cmnd *cmd)
> >> {
> >>         if (WARN_ON_ONCE(cmd->eh_eflags & SCSI_EH_ABORT_SCHEDULED))
> >>                 return;
> >>         trace_scsi_dispatch_cmd_done(cmd);
> >>         blk_complete_request(cmd->request);
> >> }
> >
> > ...seems like it should never go off because of the REQ_ATOM_COMPLETE
> > logic in the block layer, assuming that logic is working.
> >
> > Can you verify this is the intended behavior, or perhaps explain
> > what hole this patch is attempting to plug?  It seems like it is
> > dealing with the case of scsi_done() being called after a timeout
> > but before the delayed_work abort mechanism runs.  Is this actually
> > what is happening?
> >
> > Reviewed-by: Ewan D. Milne <emilne@redhat.com>
> >
> After the explanation from James B. it might indeed be handled by 
> REQ_ATOM_COMPLETE, and the real reason were the missing USB fixes.
> I've sent a test kernel with the USB fixes to our customer and wait
> for feedback there.
> 
> I'll be retracting this patchset for the time being.
> 
> Cheers,
> 
> Hannes

Just as a data point, I have a report that a kernel with these 2
patches, as well as the other 4 recent USB deadlock fixes, seems
to have resolved a duplicate completion crash.  Will try to retest
with only the first patch in this set and see what happens.

A duplicate completion crash *was* seen with just the USB fixes.

-Ewan

Re: [PATCH 0/2] scsi command timeout fixes

[James Bottomley]

On Fri, 2014-06-13 at 14:01 +0200, Hannes Reinecke wrote:
> Hi all,
> 
> I've received reports claiming they're seeing a double command completion
> occasionally when a command timeout happens.
> 
> Delving into it I found this this indeed might happening; reason being
> that the LLDD will only be informed about a timed-out command by
> calling scsi_try_to_abort_command(). Anytime before that the LLDD
> is free to assume the command is valid and might call scsi_done() on it.
> Which then will lead to interesting issues in the error handler.

Actually, I'm afraid, this reasoning isn't correct.

Completions of timed out commands are mediated by the block layer using
the REQ_ATOM_COMPLETE flag.

The reason it's an atomic flag is whoever sets it first owns the
completion.  Before a timeout fires, the timeout and completion actually
race.  If completion occurs first, the timeout may still fire, but it
will get harmlessly ignored if the REQ_ATOM_COMPLETE flag is set (it's
mediated by blk_mark_rq_complete()).

Conversely, after the timeout has fired, the flag is set and any
incoming completion gets ignored (code in blk_complete_request()).  The
atomicity of the flag should guarantee we never see double completions.

However, in between the timeout firing and us doing something with the
command in the error handler, we have to force the LLD to give it up.
This requires that we take actions to ensure that we've really killed
the command within the LLD before we start doing things with the command
in the error handler.  The way we do this is either successful abort,
which ensures the LLD won't complete the command or successful reset
which should kill all commands for the LUN/Target/Device etc.

If you're seeing double completions it's either because we have a bug in
SCSI and are doing something with the command before we know block has
relinquished it.  That's actually why this bug was so serious:

commit d555a2abf3481f81303d835046a5ec2c4fb3ca8e
Author: James Bottomley <JBottomley@Parallels.com>
Date:   Fri Mar 28 10:50:17 2014 -0700

    [SCSI] Fix spurious request sense in error handling

We'd wrongly call request sense on a timed out command and that could
cause double completions.

Assuming SCSI is correct, we can still get double completions if drivers
don't actually kill the queued command on abort or reset ... there was a
nasty bug like this within hpsa for a while.

James

Re: [PATCH 0/2] scsi command timeout fixes

[hch]

On Fri, Jun 13, 2014 at 04:52:52PM +0000, James Bottomley wrote:
> If you're seeing double completions it's either because we have a bug in
> SCSI and are doing something with the command before we know block has
> relinquished it.  That's actually why this bug was so serious:

Note that drivers or transports that implement ->eh_timed_out make
this picture even more complicated, as that adds another path
into driver control.

Hannes, what driver do you see this with?