iRiver H100 series and usb-storage issues

iRiver H100 series and usb-storage issues

[Philippe Troin]

Lads,

I've had a discussion with Matthew Dharm
<mdharm-usb@one-eyed-alien.net> on the Linux-usb mailing list
<linux-usb-users@lists.sourceforge.net> and I'm taking the topic
here...

Mailing list threads:

 http://marc.theaimsgroup.com/?l=linux-usb-users&m=108329645220736&w=2
 http://marc.theaimsgroup.com/?l=linux-usb-users&m=108332081125990&w=2
 http://marc.theaimsgroup.com/?l=linux-usb-users&m=108370356206121&w=2

Here's the problem:

 The iRiver H100 series MP3 players work with linux, but quite
 unreliably. By unreliable, I mean that repetitively md5sum'ing the
 files on the device yield different results:

   find <mountpoint> -type f -print0 | sort -z | xargs -r0 md5sum > sums.1
   find <mountpoint> -type f -print0 | sort -z | xargs -r0 md5sum > sums.2
   diff sums.1 sums.2

 will dump a bunch of diffs. Bad, bad, bad...

With vanilla 2.4.26, these kernel messages are issued and an I/O error
is returned to user space:

  USB Mass Storage device found at 18
  SCSI disk error : host 1 channel 0 id 0 lun 0 return code = 8000000
  Current sd08:21: sense key None
   I/O error: dev 08:21, sector 2225382

The sector numbers change all the time... Retrying a faulty sector
will give a good result.

After recompiling with debug message, here are the messages before and
during the error (2.4.26 too):

  usb-storage: queuecommand() called
  usb-storage: *** thread awakened.
  usb-storage: Command READ_10 (10 bytes)
  usb-storage: 28 00 01 e5 1f 5c 00 00 01 00 00 00
  usb-storage: Bulk command S 0x43425355 T 0x944 Trg 0 LUN 0 L 512 F 128 CL 10
  usb-storage: Bulk command transfer result=0
  usb-storage: usb_stor_transfer_partial(): xfer 512 bytes
  usb-storage: usb_stor_bulk_msg() returned 0 xferred 512/512
  usb-storage: usb_stor_transfer_partial(): transfer complete
  usb-storage: Bulk data transfer result 0x0
  usb-storage: Attempting to get CSW...
  usb-storage: Bulk status result = 0
  usb-storage: Bulk status Sig 0x53425355 T 0x944 R 0 Stat 0x0
  usb-storage: scsi cmd done, result=0x0
  usb-storage: *** thread sleeping.
  usb-storage: queuecommand() called
  usb-storage: *** thread awakened.
  usb-storage: Command READ_10 (10 bytes)
  usb-storage: 28 00 00 a3 e9 21 00 00 01 00 00 00
  usb-storage: Bulk command S 0x43425355 T 0x945 Trg 0 LUN 0 L 512 F 128 CL 10
  usb-storage: Bulk command transfer result=0
  usb-storage: usb_stor_transfer_partial(): xfer 512 bytes
  usb-storage: usb_stor_bulk_msg() returned 0 xferred 0/512
  usb-storage: Bulk data transfer result 0x1
  usb-storage: Attempting to get CSW...
  usb-storage: clearing endpoint halt for pipe 0xc0011e80
  usb-storage: usb_stor_clear_halt: result=0
  usb-storage: Attempting to get CSW (2nd try)...
  usb-storage: Bulk status result = 0
  usb-storage: Bulk status Sig 0x53425355 T 0x945 R 512 Stat 0x0
  usb-storage: -- unexpectedly short transfer
  usb-storage: Issuing auto-REQUEST_SENSE
  usb-storage: Bulk command S 0x43425355 T 0x946 Trg 0 LUN 0 L 18 F 128 CL 6
  usb-storage: Bulk command transfer result=0
  usb-storage: usb_stor_transfer_partial(): xfer 18 bytes
  usb-storage: usb_stor_bulk_msg() returned 0 xferred 18/18
  usb-storage: usb_stor_transfer_partial(): transfer complete
  usb-storage: Bulk data transfer result 0x0
  usb-storage: Attempting to get CSW...
  usb-storage: Bulk status result = 0
  usb-storage: Bulk status Sig 0x53425355 T 0x946 R 0 Stat 0x0
  usb-storage: -- Result from auto-sense is 0
  usb-storage: -- code: 0x70, key: 0x0, ASC: 0x0, ASCQ: 0x0
  usb-storage: No Sense: no additional sense information
  usb-storage: scsi cmd done, result=0x0
  usb-storage: *** thread sleeping.
  SCSI disk error : host 1 channel 0 id 0 lun 0 return code = 8000000
  Current sd08:21: sense key None
   I/O error: dev 08:21, sector 10741986

When using vanilla 2.6.5, I get no I/O errors, but the md5 diffs are
still generated, so there is still something wrong...

Apparently, the problem is that the device posts an empty reply to a
valid query (save an bug in linux, which I could not pinpoint (yet?)).

I have tried running the device on different computers with different
USB chipsets, and I could reproduce the problem every time.

I am posting here to see if anyone can provide any debugging help or
other clues before I call it quit.

Thanks,
Phil.

Re: iRiver H100 series and usb-storage issues

[Alan Stern]

I just noticed this thread on linux-kernel:

http://marc.theaimsgroup.com/?l=linux-kernel&m=108372064000188&w=2

Apparently under some circumstances the iRiver H100 returns 0 bytes 
transferred with GOOD status and residue=512 for a READ(10) command 
asking for 1 sector.  As far as I know this is legal, and it indicates the 
command should simply be retried.

But apparently the sd driver doesn't realize what has happened and assumes 
the transfer was successful.  If I'm right then the sd driver should be 
fixed, but I'm not sure what is the best thing to do.

James, can you offer some advice?

Alan Stern

Re: iRiver H100 series and usb-storage issues

[Philippe Troin]

Alan Stern <stern@rowland.harvard.edu> writes:

> I just noticed this thread on linux-kernel:
> 
> http://marc.theaimsgroup.com/?l=linux-kernel&m=108372064000188&w=2
> 
> Apparently under some circumstances the iRiver H100 returns 0 bytes 
> transferred with GOOD status and residue=512 for a READ(10) command 
> asking for 1 sector.  As far as I know this is legal, and it indicates the 
> command should simply be retried.

That's correct.  However, the iRiver H1xx will also commit a USB
protocol violation by not returning a CSW (Command Status
Wrapper).  That's what screws up the transfer.
 
> But apparently the sd driver doesn't realize what has happened and assumes 
> the transfer was successful.  If I'm right then the sd driver should be 
> fixed, but I'm not sure what is the best thing to do.

I am not sure the SCSI layer can recover given that the USB layer is
confused...

Please note that:

 1. I am just repeating what I have been told by various people and
    claim no knowledge of the USB or SCSI layers.  In other words, I
    could be all wrong :-)

 2. I do not own a H1xx anymore, having returned mine.
 
Phil.

Re: iRiver H100 series and usb-storage issues

[Alan Stern]

On 7 Jun 2004, Philippe Troin wrote:

> Alan Stern <stern@rowland.harvard.edu> writes:
> 
> > I just noticed this thread on linux-kernel:
> > 
> > http://marc.theaimsgroup.com/?l=linux-kernel&m=108372064000188&w=2
> > 
> > Apparently under some circumstances the iRiver H100 returns 0 bytes 
> > transferred with GOOD status and residue=512 for a READ(10) command 
> > asking for 1 sector.  As far as I know this is legal, and it indicates the 
> > command should simply be retried.
> 
> That's correct.  However, the iRiver H1xx will also commit a USB
> protocol violation by not returning a CSW (Command Status
> Wrapper).  That's what screws up the transfer.

In the log you posted (at the URL above) the CSW was returned correctly.  
The same is true for the messages you referred to.  So that was not the 
source of the problem.

> Please note that:
> 
>  1. I am just repeating what I have been told by various people and
>     claim no knowledge of the USB or SCSI layers.  In other words, I
>     could be all wrong :-)
> 
>  2. I do not own a H1xx anymore, having returned mine.

Do you know of anyone who has contributed to any versions of this thread 
and still does have an H1xx?

Alan Stern

Re: iRiver H100 series and usb-storage issues

[Philippe Troin]

Alan Stern <stern@rowland.harvard.edu> writes:

> On 7 Jun 2004, Philippe Troin wrote:
> 
> > Alan Stern <stern@rowland.harvard.edu> writes:
> > 
> > > I just noticed this thread on linux-kernel:
> > > 
> > > http://marc.theaimsgroup.com/?l=linux-kernel&m=108372064000188&w=2
> > > 
> > > Apparently under some circumstances the iRiver H100 returns 0 bytes 
> > > transferred with GOOD status and residue=512 for a READ(10) command 
> > > asking for 1 sector.  As far as I know this is legal, and it indicates the 
> > > command should simply be retried.
> > 
> > That's correct.  However, the iRiver H1xx will also commit a USB
> > protocol violation by not returning a CSW (Command Status
> > Wrapper).  That's what screws up the transfer.
> 
> In the log you posted (at the URL above) the CSW was returned correctly.  
> The same is true for the messages you referred to.  So that was not the 
> source of the problem.

Okay, quite possibly, as I was pointing out I am mostly clueless
w.r.t. USB.  But what about:

  usb-storage: usb_stor_transfer_partial(): xfer 512 bytes
  usb-storage: usb_stor_bulk_msg() returned 0 xferred 0/512
  usb-storage: Bulk data transfer result 0x1
  usb-storage: Attempting to get CSW...
               ^^^^^^^^^^^^^^^^^^^^^^^^
  usb-storage: clearing endpoint halt for pipe 0xc0011e80
  usb-storage: usb_stor_clear_halt: result=0
  usb-storage: Attempting to get CSW (2nd try)...
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  usb-storage: Bulk status result = 0
  usb-storage: Bulk status Sig 0x53425355 T 0x945 R 512 Stat 0x0
  usb-storage: -- unexpectedly short transfer
  usb-storage: Issuing auto-REQUEST_SENSE

> > Please note that:
> > 
> >  1. I am just repeating what I have been told by various people and
> >     claim no knowledge of the USB or SCSI layers.  In other words, I
> >     could be all wrong :-)
> > 
> >  2. I do not own a H1xx anymore, having returned mine.
> 
> Do you know of anyone who has contributed to any versions of this thread 
> and still does have an H1xx?

No, I did not keep track.  Nothing prevents me from "trying" another
one if you're serious about fixing the above issues.

Phil.

Re: iRiver H100 series and usb-storage issues

[Alan Stern]

On 7 Jun 2004, Philippe Troin wrote:

> Alan Stern <stern@rowland.harvard.edu> writes:
> 
> > In the log you posted (at the URL above) the CSW was returned correctly.  
> > The same is true for the messages you referred to.  So that was not the 
> > source of the problem.
> 
> Okay, quite possibly, as I was pointing out I am mostly clueless
> w.r.t. USB.  But what about:
> 
>   usb-storage: usb_stor_transfer_partial(): xfer 512 bytes
>   usb-storage: usb_stor_bulk_msg() returned 0 xferred 0/512
>   usb-storage: Bulk data transfer result 0x1
>   usb-storage: Attempting to get CSW...
>                ^^^^^^^^^^^^^^^^^^^^^^^^
>   usb-storage: clearing endpoint halt for pipe 0xc0011e80
>   usb-storage: usb_stor_clear_halt: result=0
>   usb-storage: Attempting to get CSW (2nd try)...
>                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
>   usb-storage: Bulk status result = 0
>   usb-storage: Bulk status Sig 0x53425355 T 0x945 R 512 Stat 0x0
>   usb-storage: -- unexpectedly short transfer
>   usb-storage: Issuing auto-REQUEST_SENSE

Those are perfectly normal.  The spec allows a device to halt the 
bulk-in endpoint the first time the host tries to read the CSW.  The 
second attempted read is supposed to succeed, and indeed it did.

> > Do you know of anyone who has contributed to any versions of this thread 
> > and still does have an H1xx?
> 
> No, I did not keep track.  Nothing prevents me from "trying" another
> one if you're serious about fixing the above issues.

I am serious about fixing this.  At the moment we don't have anything new
for you to try, but maybe we'll come up with something soon.  I'm still
waiting to hear from the SCSI people about how this should be handled...

Alan Stern