Need help with handling failed ATA pass-through command and sense data

Need help with handling failed ATA pass-through command and sense data

[Alan Stern]

This is in reference to

	https://bugzilla.redhat.com/show_bug.cgi?id=1351305

The problem is that some program (probably udisks2) periodically sends
the following ATA pass-through command to a USB-ATA bridge attached to
a Western Digital drive:

	85062000 00000000 00000000 0000e500

I don't know what this command does (some sort of reset?).  The command
fails and the device returns the following sense data:

	72000000 0000000e 090c0000 00ff0000 00000000 0050

I don't know how to decode this -- I don't have copies of the relevant
documents.  Can anybody decode this for me?

Anyway, the SCSI core treats it as a Hardware Error and puts warning
messages in the kernel log:

[17244.280612] sd 7:0:0:0: [sdd] tag#0 FAILED Result: hostbyte=DID_ERROR driverbyte=DRIVER_SENSE
[17244.280614] sd 7:0:0:0: [sdd] tag#0 Sense Key : Hardware Error [current] [descriptor] 
[17244.280616] sd 7:0:0:0: [sdd] tag#0 Add. Sense: No additional sense information
[17244.280618] sd 7:0:0:0: [sdd] tag#0 CDB: ATA command pass through(16) 85 06 20 00 00 00 00 00 00 00 00 00 00 00 e5 00

Is this really the right thing to do?  Could it be that we are failing 
to interpret this sense data correctly?

Other commands provoke similar responses from the device, but without 
obnoxious log messages.  For example, the command:

	85082e00 00000100 00000000 0000ec00

fails with the following sense data:

	72000000 0000000e 090c0000 00000000 00000000 0050

and no output to the log.  I don't know why the behavior is different.  
There are other similar examples, with and without log messages.

Any help would be appreciated.

Alan Stern

Re: Need help with handling failed ATA pass-through command and sense data

[Ewan D. Milne]

On Thu, 2017-05-18 at 10:35 -0400, Alan Stern wrote:
> This is in reference to
> 
> 	https://bugzilla.redhat.com/show_bug.cgi?id=1351305
> 
> The problem is that some program (probably udisks2) periodically sends
> the following ATA pass-through command to a USB-ATA bridge attached to
> a Western Digital drive:
> 
> 	85062000 00000000 00000000 0000e500

According to T10 SAT-4 this is an ATA PASS-THROUGH(16) command, with
PROTOCOL=3 (non-data), CK_COND=1, COMMAND=E5h (the ATA command).

> 
> I don't know what this command does (some sort of reset?).  The command
> fails and the device returns the following sense data:
> 
> 	72000000 0000000e 090c0000 00ff0000 00000000 0050
> 
> I don't know how to decode this -- I don't have copies of the relevant
> documents.  Can anybody decode this for me?

This is a current descriptor format sense data wih a single
ATA Status Return sense data descriptor (beginning at 8 bytes into
the sense data buffer 090c...)  The relevant fields are COUNT=255 LBA=0
and STATUS=50h (which I suspect is what is the interesting part).

> 
> Anyway, the SCSI core treats it as a Hardware Error and puts warning
> messages in the kernel log:
> 
> [17244.280612] sd 7:0:0:0: [sdd] tag#0 FAILED Result: hostbyte=DID_ERROR driverbyte=DRIVER_SENSE
> [17244.280614] sd 7:0:0:0: [sdd] tag#0 Sense Key : Hardware Error [current] [descriptor] 
> [17244.280616] sd 7:0:0:0: [sdd] tag#0 Add. Sense: No additional sense information
> [17244.280618] sd 7:0:0:0: [sdd] tag#0 CDB: ATA command pass through(16) 85 06 20 00 00 00 00 00 00 00 00 00 00 00 e5 00
> 
> Is this really the right thing to do?  Could it be that we are failing 
> to interpret this sense data correctly?

With the 72000000 0000000e 090c0000 00ff0000 00000000 0050 sense data
buffer above scsi_sense_key_string() should have returned "No Sense" as
the array value is 0.  Even if we somehow managed to fail to correctly
interpret descriptor format sense vs. fixed format sense.

> 
> Other commands provoke similar responses from the device, but without 
> obnoxious log messages.  For example, the command:
> 
> 	85082e00 00000100 00000000 0000ec00
> 
> fails with the following sense data:
> 
> 	72000000 0000000e 090c0000 00000000 00000000 0050
> 
> and no output to the log.  I don't know why the behavior is different.  
> There are other similar examples, with and without log messages.

It seems more likely that somehow there is a path where the wrong or
uninitialized sshdr structure is being passed to the logging routine.

-Ewan

> 
> Any help would be appreciated.
> 
> Alan Stern
> 

Re: Need help with handling failed ATA pass-through command and sense data

[Ewan D. Milne]

On Thu, 2017-05-18 at 11:34 -0400, Ewan D. Milne wrote:
> On Thu, 2017-05-18 at 10:35 -0400, Alan Stern wrote:
> > This is in reference to
> > 
> > 	https://bugzilla.redhat.com/show_bug.cgi?id=1351305
> > 
> > The problem is that some program (probably udisks2) periodically sends
> > the following ATA pass-through command to a USB-ATA bridge attached to
> > a Western Digital drive:
> > 
> > 	85062000 00000000 00000000 0000e500
> 
> According to T10 SAT-4 this is an ATA PASS-THROUGH(16) command, with
> PROTOCOL=3 (non-data), CK_COND=1, COMMAND=E5h (the ATA command).
> 
> > 
> > I don't know what this command does (some sort of reset?).  The command
> > fails and the device returns the following sense data:
> > 
> > 	72000000 0000000e 090c0000 00ff0000 00000000 0050
> > 
> > I don't know how to decode this -- I don't have copies of the relevant
> > documents.  Can anybody decode this for me?
> 
> This is a current descriptor format sense data wih a single
> ATA Status Return sense data descriptor (beginning at 8 bytes into
> the sense data buffer 090c...)  The relevant fields are COUNT=255 LBA=0
> and STATUS=50h (which I suspect is what is the interesting part).
> 
> > 
> > Anyway, the SCSI core treats it as a Hardware Error and puts warning
> > messages in the kernel log:
> > 
> > [17244.280612] sd 7:0:0:0: [sdd] tag#0 FAILED Result: hostbyte=DID_ERROR driverbyte=DRIVER_SENSE
> > [17244.280614] sd 7:0:0:0: [sdd] tag#0 Sense Key : Hardware Error [current] [descriptor] 
> > [17244.280616] sd 7:0:0:0: [sdd] tag#0 Add. Sense: No additional sense information
> > [17244.280618] sd 7:0:0:0: [sdd] tag#0 CDB: ATA command pass through(16) 85 06 20 00 00 00 00 00 00 00 00 00 00 00 e5 00
> > 
> > Is this really the right thing to do?  Could it be that we are failing 
> > to interpret this sense data correctly?
> 
> With the 72000000 0000000e 090c0000 00ff0000 00000000 0050 sense data
> buffer above scsi_sense_key_string() should have returned "No Sense" as
> the array value is 0.  Even if we somehow managed to fail to correctly
> interpret descriptor format sense vs. fixed format sense.
> 
> > 
> > Other commands provoke similar responses from the device, but without 
> > obnoxious log messages.  For example, the command:
> > 
> > 	85082e00 00000100 00000000 0000ec00
> > 
> > fails with the following sense data:
> > 
> > 	72000000 0000000e 090c0000 00000000 00000000 0050
> > 
> > and no output to the log.  I don't know why the behavior is different.  
> > There are other similar examples, with and without log messages.
> 
> It seems more likely that somehow there is a path where the wrong or
> uninitialized sshdr structure is being passed to the logging routine.
> 
> -Ewan

Oh, wait.  You said USB-ATA bridge.

There is this code in drivers/usb/storage/transport.c:
Perhaps this is responsible.  It is forcing the sense key to
HARDWARE_ERROR under certain conditions.  That would cause the
logging message you see to be output.

                /*                                                                                                                                                                                                 
                 * We often get empty sense data.  This could indicate that                                                                                                                                        
                 * everything worked or that there was an unspecified                                                                                                                                              
                 * problem.  We have to decide which.                                                                                                                                                              
                 */
                if (sshdr.sense_key == 0 && sshdr.asc == 0 && sshdr.ascq == 0 &&
                    fm_ili == 0) {
                        /*                                                                                                                                                                                         
                         * If things are really okay, then let's show that.                                                                                                                                        
                         * Zero out the sense buffer so the higher layers                                                                                                                                          
                         * won't realize we did an unsolicited auto-sense.                                                                                                                                         
                         */
                        if (result == USB_STOR_TRANSPORT_GOOD) {
                                srb->result = SAM_STAT_GOOD;
                                srb->sense_buffer[0] = 0x0;

                        /*                                                                                                                                                                                         
                         * If there was a problem, report an unspecified                                                                                                                                           
                         * hardware error to prevent the higher layers from                                                                                                                                        
                         * entering an infinite retry loop.                                                                                                                                                        
                         */
                        } else {
                                srb->result = DID_ERROR << 16;
                                if ((sshdr.response_code & 0x72) == 0x72)
                                        srb->sense_buffer[1] = HARDWARE_ERROR;
                                else
                                        srb->sense_buffer[2] = HARDWARE_ERROR;
                        }
                }

> 
> > 
> > Any help would be appreciated.
> > 
> > Alan Stern
> > 
> 
> 

Re: Need help with handling failed ATA pass-through command and sense data

[Alan Stern]

On Thu, 18 May 2017, Ewan D. Milne wrote:

> On Thu, 2017-05-18 at 11:34 -0400, Ewan D. Milne wrote:
> > On Thu, 2017-05-18 at 10:35 -0400, Alan Stern wrote:
> > > This is in reference to
> > > 
> > > 	https://bugzilla.redhat.com/show_bug.cgi?id=1351305
> > > 
> > > The problem is that some program (probably udisks2) periodically sends
> > > the following ATA pass-through command to a USB-ATA bridge attached to
> > > a Western Digital drive:
> > > 
> > > 	85062000 00000000 00000000 0000e500
> > 
> > According to T10 SAT-4 this is an ATA PASS-THROUGH(16) command, with
> > PROTOCOL=3 (non-data), CK_COND=1, COMMAND=E5h (the ATA command).
> > 
> > > 
> > > I don't know what this command does (some sort of reset?).  The command
> > > fails and the device returns the following sense data:
> > > 
> > > 	72000000 0000000e 090c0000 00ff0000 00000000 0050
> > > 
> > > I don't know how to decode this -- I don't have copies of the relevant
> > > documents.  Can anybody decode this for me?
> > 
> > This is a current descriptor format sense data wih a single
> > ATA Status Return sense data descriptor (beginning at 8 bytes into
> > the sense data buffer 090c...)  The relevant fields are COUNT=255 LBA=0
> > and STATUS=50h (which I suspect is what is the interesting part).
> > 
> > > 
> > > Anyway, the SCSI core treats it as a Hardware Error and puts warning
> > > messages in the kernel log:
> > > 
> > > [17244.280612] sd 7:0:0:0: [sdd] tag#0 FAILED Result: hostbyte=DID_ERROR driverbyte=DRIVER_SENSE
> > > [17244.280614] sd 7:0:0:0: [sdd] tag#0 Sense Key : Hardware Error [current] [descriptor] 
> > > [17244.280616] sd 7:0:0:0: [sdd] tag#0 Add. Sense: No additional sense information
> > > [17244.280618] sd 7:0:0:0: [sdd] tag#0 CDB: ATA command pass through(16) 85 06 20 00 00 00 00 00 00 00 00 00 00 00 e5 00
> > > 
> > > Is this really the right thing to do?  Could it be that we are failing 
> > > to interpret this sense data correctly?
> > 
> > With the 72000000 0000000e 090c0000 00ff0000 00000000 0050 sense data
> > buffer above scsi_sense_key_string() should have returned "No Sense" as
> > the array value is 0.  Even if we somehow managed to fail to correctly
> > interpret descriptor format sense vs. fixed format sense.
> > 
> > > 
> > > Other commands provoke similar responses from the device, but without 
> > > obnoxious log messages.  For example, the command:
> > > 
> > > 	85082e00 00000100 00000000 0000ec00
> > > 
> > > fails with the following sense data:
> > > 
> > > 	72000000 0000000e 090c0000 00000000 00000000 0050
> > > 
> > > and no output to the log.  I don't know why the behavior is different.  
> > > There are other similar examples, with and without log messages.
> > 
> > It seems more likely that somehow there is a path where the wrong or
> > uninitialized sshdr structure is being passed to the logging routine.
> > 
> > -Ewan
> 
> Oh, wait.  You said USB-ATA bridge.
> 
> There is this code in drivers/usb/storage/transport.c:
> Perhaps this is responsible.  It is forcing the sense key to
> HARDWARE_ERROR under certain conditions.  That would cause the
> logging message you see to be output.
> 
>                 /*                                                                                                                                                                                                 
>                  * We often get empty sense data.  This could indicate that                                                                                                                                        
>                  * everything worked or that there was an unspecified                                                                                                                                              
>                  * problem.  We have to decide which.                                                                                                                                                              
>                  */
>                 if (sshdr.sense_key == 0 && sshdr.asc == 0 && sshdr.ascq == 0 &&
>                     fm_ili == 0) {
>                         /*                                                                                                                                                                                         
>                          * If things are really okay, then let's show that.                                                                                                                                        
>                          * Zero out the sense buffer so the higher layers                                                                                                                                          
>                          * won't realize we did an unsolicited auto-sense.                                                                                                                                         
>                          */
>                         if (result == USB_STOR_TRANSPORT_GOOD) {
>                                 srb->result = SAM_STAT_GOOD;
>                                 srb->sense_buffer[0] = 0x0;
> 
>                         /*                                                                                                                                                                                         
>                          * If there was a problem, report an unspecified                                                                                                                                           
>                          * hardware error to prevent the higher layers from                                                                                                                                        
>                          * entering an infinite retry loop.                                                                                                                                                        
>                          */
>                         } else {
>                                 srb->result = DID_ERROR << 16;
>                                 if ((sshdr.response_code & 0x72) == 0x72)
>                                         srb->sense_buffer[1] = HARDWARE_ERROR;
>                                 else
>                                         srb->sense_buffer[2] = HARDWARE_ERROR;
>                         }
>                 }

I had completely forgotten about this code.  :-(

Looks like you put your finger on the source of the problem.  So if the 
device sends back essentially empty sense data (SK = No Sense, ASC = 
ASCQ = 0), but the USB transport indicates command failure, how should 
we inform the SCSI core in a way that won't cause infinite retries or 
obnoxious log messages?

Should we be doing a better job of detecting empty sense data -- that 
is, do we need to check for non-empty ATA status?

Or has the SCSI core improved so that it no longer does infinite
retries (see commit f1a0743bc0e7 "USB: storage: When a device returns
no sense data, call it a Hardware Error" and Bugzilla entry #14118),
meaning that this code can be removed entirely?

Alan Stern

Re: Need help with handling failed ATA pass-through command and sense data

[Ewan D. Milne]

On Thu, 2017-05-18 at 13:37 -0400, Alan Stern wrote:
> 
> I had completely forgotten about this code.  :-(
> 
> Looks like you put your finger on the source of the problem.  So if the 
> device sends back essentially empty sense data (SK = No Sense, ASC = 
> ASCQ = 0), but the USB transport indicates command failure, how should 
> we inform the SCSI core in a way that won't cause infinite retries or 
> obnoxious log messages?
> 
> Should we be doing a better job of detecting empty sense data -- that 
> is, do we need to check for non-empty ATA status?
> 
> Or has the SCSI core improved so that it no longer does infinite
> retries (see commit f1a0743bc0e7 "USB: storage: When a device returns
> no sense data, call it a Hardware Error" and Bugzilla entry #14118),
> meaning that this code can be removed entirely?
> 
> Alan Stern

We added:

commit ee60b2c52ec8ecdcbcd2f85cc117b525f649441f
Author: Eiichi Tsukata <eiichi.tsukata.xh@hitachi.com>
Date:   Tue Feb 11 14:29:52 2014 +0900

    [SCSI] Add timeout to avoid infinite command retry

but this may not give you the behavior you want, because it bounds
the execution time to (# of retries + 1) * timeout.  So if you get
an immediate error return it could still take a while for this code
to give up retrying, i.e. it does not have the same properties as
your commit f1a0743bc0e7.

I suppose you could decode the ATA Status Return sense data descriptor
but I don't know how good the compliance is among all the ATA devices.
Table 177 in section 1.2.2.8 of SAT-4 r06 seems to say that most of
the fields in the sense data are unspecified for ATA PASS-THROUGH
commands, so this probably explains why you see nothing else useful.
Perhaps the logging should be delegated to the USB or ATA code for
these commands, since they are not really part of SCSI?

I have seen a case of a Fibre Channel array returning all zeroes
in the sense data, but this was because it was malfunctioning.

-Ewan

Re: Need help with handling failed ATA pass-through command and sense data

[Alan Stern]

On Thu, 18 May 2017, Ewan D. Milne wrote:

> On Thu, 2017-05-18 at 13:37 -0400, Alan Stern wrote:
> > 
> > I had completely forgotten about this code.  :-(
> > 
> > Looks like you put your finger on the source of the problem.  So if the 
> > device sends back essentially empty sense data (SK = No Sense, ASC = 
> > ASCQ = 0), but the USB transport indicates command failure, how should 
> > we inform the SCSI core in a way that won't cause infinite retries or 
> > obnoxious log messages?
> > 
> > Should we be doing a better job of detecting empty sense data -- that 
> > is, do we need to check for non-empty ATA status?
> > 
> > Or has the SCSI core improved so that it no longer does infinite
> > retries (see commit f1a0743bc0e7 "USB: storage: When a device returns
> > no sense data, call it a Hardware Error" and Bugzilla entry #14118),
> > meaning that this code can be removed entirely?
> > 
> > Alan Stern
> 
> We added:
> 
> commit ee60b2c52ec8ecdcbcd2f85cc117b525f649441f
> Author: Eiichi Tsukata <eiichi.tsukata.xh@hitachi.com>
> Date:   Tue Feb 11 14:29:52 2014 +0900
> 
>     [SCSI] Add timeout to avoid infinite command retry
> 
> but this may not give you the behavior you want, because it bounds
> the execution time to (# of retries + 1) * timeout.  So if you get
> an immediate error return it could still take a while for this code
> to give up retrying, i.e. it does not have the same properties as
> your commit f1a0743bc0e7.
> 
> I suppose you could decode the ATA Status Return sense data descriptor
> but I don't know how good the compliance is among all the ATA devices.
> Table 177 in section 1.2.2.8 of SAT-4 r06 seems to say that most of
> the fields in the sense data are unspecified for ATA PASS-THROUGH
> commands, so this probably explains why you see nothing else useful.
> Perhaps the logging should be delegated to the USB or ATA code for
> these commands, since they are not really part of SCSI?
> 
> I have seen a case of a Fibre Channel array returning all zeroes
> in the sense data, but this was because it was malfunctioning.

All right, suppose we don't return DID_ERROR and don't call it a
hardware error.  I don't know if this will help at all, and I don't
know if it will cause any regressions.

GeekGirl1, can you try applying the patch below to see if it makes any 
difference?  If you don't know how, I will attach it to the Bugzilla 
report so somebody else can try it.

Alan Stern




Index: usb-4.x/drivers/usb/storage/transport.c
===================================================================
--- usb-4.x.orig/drivers/usb/storage/transport.c
+++ usb-4.x/drivers/usb/storage/transport.c
@@ -835,6 +835,7 @@ Retry_Sense:
 				srb->result = SAM_STAT_GOOD;
 				srb->sense_buffer[0] = 0x0;
 
+#if 0
 			/*
 			 * If there was a problem, report an unspecified
 			 * hardware error to prevent the higher layers from
@@ -846,6 +847,7 @@ Retry_Sense:
 					srb->sense_buffer[1] = HARDWARE_ERROR;
 				else
 					srb->sense_buffer[2] = HARDWARE_ERROR;
+#endif
 			}
 		}
 	}

Re: Need help with handling failed ATA pass-through command and sense data

[mail1]

Sorry, I don't have the experience to do this quickly. I'm out of practice building a kernel and will need time to re-learn a few things.

Can you please update the bug report and ask for someone else to try it? In the mean time, I'll do what I can.

--GeekGirl1

On 05/23/2017 02:34 PM, Alan Stern wrote:
> On Thu, 18 May 2017, Ewan D. Milne wrote:
>
>> On Thu, 2017-05-18 at 13:37 -0400, Alan Stern wrote:
>>> I had completely forgotten about this code.  :-(
>>>
>>> Looks like you put your finger on the source of the problem.  So if the
>>> device sends back essentially empty sense data (SK = No Sense, ASC =
>>> ASCQ = 0), but the USB transport indicates command failure, how should
>>> we inform the SCSI core in a way that won't cause infinite retries or
>>> obnoxious log messages?
>>>
>>> Should we be doing a better job of detecting empty sense data -- that
>>> is, do we need to check for non-empty ATA status?
>>>
>>> Or has the SCSI core improved so that it no longer does infinite
>>> retries (see commit f1a0743bc0e7 "USB: storage: When a device returns
>>> no sense data, call it a Hardware Error" and Bugzilla entry #14118),
>>> meaning that this code can be removed entirely?
>>>
>>> Alan Stern
>> We added:
>>
>> commit ee60b2c52ec8ecdcbcd2f85cc117b525f649441f
>> Author: Eiichi Tsukata <eiichi.tsukata.xh@hitachi.com>
>> Date:   Tue Feb 11 14:29:52 2014 +0900
>>
>>      [SCSI] Add timeout to avoid infinite command retry
>>
>> but this may not give you the behavior you want, because it bounds
>> the execution time to (# of retries + 1) * timeout.  So if you get
>> an immediate error return it could still take a while for this code
>> to give up retrying, i.e. it does not have the same properties as
>> your commit f1a0743bc0e7.
>>
>> I suppose you could decode the ATA Status Return sense data descriptor
>> but I don't know how good the compliance is among all the ATA devices.
>> Table 177 in section 1.2.2.8 of SAT-4 r06 seems to say that most of
>> the fields in the sense data are unspecified for ATA PASS-THROUGH
>> commands, so this probably explains why you see nothing else useful.
>> Perhaps the logging should be delegated to the USB or ATA code for
>> these commands, since they are not really part of SCSI?
>>
>> I have seen a case of a Fibre Channel array returning all zeroes
>> in the sense data, but this was because it was malfunctioning.
> All right, suppose we don't return DID_ERROR and don't call it a
> hardware error.  I don't know if this will help at all, and I don't
> know if it will cause any regressions.
>
> GeekGirl1, can you try applying the patch below to see if it makes any
> difference?  If you don't know how, I will attach it to the Bugzilla
> report so somebody else can try it.
>
> Alan Stern
>
>
>
>
> Index: usb-4.x/drivers/usb/storage/transport.c
> ===================================================================
> --- usb-4.x.orig/drivers/usb/storage/transport.c
> +++ usb-4.x/drivers/usb/storage/transport.c
> @@ -835,6 +835,7 @@ Retry_Sense:
>   				srb->result = SAM_STAT_GOOD;
>   				srb->sense_buffer[0] = 0x0;
>   
> +#if 0
>   			/*
>   			 * If there was a problem, report an unspecified
>   			 * hardware error to prevent the higher layers from
> @@ -846,6 +847,7 @@ Retry_Sense:
>   					srb->sense_buffer[1] = HARDWARE_ERROR;
>   				else
>   					srb->sense_buffer[2] = HARDWARE_ERROR;
> +#endif
>   			}
>   		}
>   	}
>
>