To be sure, I did some extended testing with it hooked up: Tried
doing a full and incremental backup of my machine with no errors reported,
as well as an offline and then immediately afterwards, long test via
smartctl. Nothing changed in the output.
I've attached the output of smartctl at various points in the tests:
the first being the initial immediate display of information at startup, the
second just after the long test, and the third just after the two backups
(Full and incremental) were tried. Nothing seems to shout at me in the
output, I'm frankly pretty sure something's wrong with the enclosure. If
it's the drive, it's not showing up here at least.
I'd like your thoughts and suggestions on this. While I'm pretty
sure I know what the smartctl output means, I'm always capable of being
entirely wrong. Please let me know if I've misinterpreted the information.
Timothy McGrath
On Mon 23-11-09 03:09:19, tmhi...@gmail.com wrote:
> Okay, finally had some time to dismantle the machine in question and
> inserted the backup drive without the enclosure. Now that I was able to get
> smartctl to give me information on what was going on, it seems there's
> nothing wrong with the drive itself (no remapped sectors, nothing prefail or
> fail going wrong, drive's smart status is good) but it's had a history of
> 406 (!!!) errors reported, the last five happening within the same second,
> all of which seem (to my untrained eye) to imply a bad IDE cable. Which
> means likely my USB enclosure is screwing up.
>
> To be sure, I did some extended testing with it hooked up: Tried
> doing a full and incremental backup of my machine with no errors reported,
> as well as an offline and then immediately afterwards, long test via
> smartctl. Nothing changed in the output.
Yeah, from what you write, it looks like USB enclosure is at fault (or it
could still be your USB controller but I doubt it). It's still a bit
bothering that the error reported by the drive was not properly propagated
up to VFS. Either it's some block layer retry/ignore magic that I missed or
we ignore errors from block layer in some place.
Honza
--
Jan Kara <ja...@suse.cz>
SUSE Labs, CR
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majo...@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
> On Mon 23-11-09 10:06:03, Alan Stern wrote:
> > On Mon, 23 Nov 2009, Jan Kara wrote:
> >
> > > Yeah, from what you write, it looks like USB enclosure is at fault (or it
> > > could still be your USB controller but I doubt it). It's still a bit
> > > bothering that the error reported by the drive was not properly propagated
> > > up to VFS. Either it's some block layer retry/ignore magic that I missed or
> > > we ignore errors from block layer in some place.
> >
> > Is there any interest in tracking this down? It's not hard to find out
> > what low-level errors are being reported and to generate them on demand
> > with an emulated USB disk drive.
> Well, if you could provide me with the patch, I could try to track down
> why the errors aren't propagated... It would be interesting because if it's
> not some retry logic in block layer, it's a bug in VFS ;).
I can't provide a patch without first knowing what the errors are. The
way to find out is to use usbmon. See Documentation/usb/usbmon.txt for
instructions.
Alan Stern
Honza
Tim McGrath
root@roll:/home/tm# mount
/dev/root on / type ext4 (rw,relatime,barrier=1,data=ordered,data_err=abort)
proc on /proc type proc (rw)
sysfs on /sys type sysfs (rw)
usbfs on /proc/bus/usb type usbfs (rw)
none_debugs on /sys/kernel/debug type debugfs (rw)
I receive this message when I test if usbmon's directory exists:
root@roll:/home/tm# ls /sys/kernel/debug/usbmon
ls: cannot access /sys/kernel/debug/usbmon: No such file or directory
According to the kernel documentation usbmon should be loaded already. Help?
Timothy McGrath
> Uhh, this could be a problem. CONFIG_USB_MON=y is set in my .config BUT,
> although I followed the directions and debugfs is mounted,
>
> root@roll:/home/tm# mount
> /dev/root on / type ext4 (rw,relatime,barrier=1,data=ordered,data_err=abort)
> proc on /proc type proc (rw)
> sysfs on /sys type sysfs (rw)
> usbfs on /proc/bus/usb type usbfs (rw)
> none_debugs on /sys/kernel/debug type debugfs (rw)
>
> I receive this message when I test if usbmon's directory exists:
>
> root@roll:/home/tm# ls /sys/kernel/debug/usbmon
> ls: cannot access /sys/kernel/debug/usbmon: No such file or directory
>
> According to the kernel documentation usbmon should be loaded already. Help?
The documentation is slightly out of date. The usbmon directory has
been moved down a level, to /sys/kernel/debug/usb/usbmon.
Alan Stern
Thank you. I've gotten output of it screwing up, but it's a 62MB file. I
don't think I'm allowed to send attachments here, nor do I know what I'm
supposed to be looking for in this output. So, instead I'm putting the
(compressed) file up on my home computer. If you've got suggestions for what
I should use instead, let me know.
http://hikaru.no-ip.info:3000/1.mon.out.xz
Although I don't think you'll need it, I've included the dmesg output of
what happened when I ran my backup script, just in case it helps at all.
Thanks for the help so far,
Tim McGrath
usb 1-6: new high speed USB device using ehci_hcd and address 2
usb 1-6: New USB device found, idVendor=0471, idProduct=0332
usb 1-6: New USB device strings: Mfr=2, Product=1, SerialNumber=0
usb 1-6: Product: Philips SPC 1000NC Webcam
usb 1-6: Manufacturer: Philips CE
usb 1-6: configuration #1 chosen from 1 choice
2:3:1: cannot get freq at ep 0x84
usbcore: registered new interface driver snd-usb-audio
usb 1-3: new high speed USB device using ehci_hcd and address 3
usb 1-3: New USB device found, idVendor=067b, idProduct=2506
usb 1-3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
usb 1-3: Product: Mass Storage Device
usb 1-3: Manufacturer: Prolific Technology Inc.
usb 1-3: SerialNumber: 0
usb 1-3: configuration #1 chosen from 1 choice
Initializing USB Mass Storage driver...
scsi0 : SCSI emulation for USB Mass Storage devices
usbcore: registered new interface driver usb-storage
USB Mass Storage support registered.
usb-storage: device found at 3
usb-storage: waiting for device to settle before scanning
scsi 0:0:0:0: Direct-Access ST325082 3A 3.06 PQ: 0 ANSI: 0
usb-storage: device scan complete
sd 0:0:0:0: [sda] 488397168 512-byte logical blocks: (250 GB/232 GiB)
sd 0:0:0:0: [sda] Write Protect is off
sd 0:0:0:0: [sda] Mode Sense: 03 00 00 00
sd 0:0:0:0: [sda] Assuming drive cache: write through
sd 0:0:0:0: [sda] Assuming drive cache: write through
sda: sda1
sd 0:0:0:0: [sda] Assuming drive cache: write through
sd 0:0:0:0: [sda] Attached SCSI disk
sd 0:0:0:0: Attached scsi generic sg0 type 0
usb 1-6: USB disconnect, address 2
EXT4-fs (sda1): barriers enabled
kjournald2 starting: pid 9416, dev sda1:8, commit interval 5 seconds
EXT4-fs (sda1): internal journal on sda1:8
EXT4-fs (sda1): delayed allocation enabled
EXT4-fs: file extents enabled
EXT4-fs: mballoc enabled
EXT4-fs (sda1): mounted filesystem with ordered data mode
sd 0:0:0:0: [sda] Unhandled error code
sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
end_request: I/O error, dev sda, sector 44783
sd 0:0:0:0: [sda] Unhandled error code
sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
end_request: I/O error, dev sda, sector 51823
> Thank you. I've gotten output of it screwing up, but it's a 62MB file. I
> don't think I'm allowed to send attachments here, nor do I know what I'm
> supposed to be looking for in this output. So, instead I'm putting the
> (compressed) file up on my home computer. If you've got suggestions for what
> I should use instead, let me know.
>
> http://hikaru.no-ip.info:3000/1.mon.out.xz
>
> Although I don't think you'll need it, I've included the dmesg output of
> what happened when I ran my backup script, just in case it helps at all.
Here's an annotated example of one of those hiccups:
f1aa1f00 2416018820 S Bo:1:003:1 -115 31 = 55534243 07050100 00100000 80000a28 000000ae ef000008 00000000 000000
f1aa1f00 2416018929 C Bo:1:003:1 0 31 >
The computer issued a READ command for 8 blocks (4096 bytes) starting
at block number 0x0000aeef = 44783.
d2588b00 2416019342 S Bi:1:003:2 -115 4096 <
d2588b00 2416019428 C Bi:1:003:2 -32 0
f1aa1f00 2416019435 S Co:1:003:0 s 02 01 0000 0082 0000 0
f1aa1f00 2416019554 C Co:1:003:0 0 0
The drive returned 0 bytes of data.
f1aa1f00 2416019560 S Bi:1:003:2 -115 13 <
f1aa1f00 2416019678 C Bi:1:003:2 0 13 = 55534253 07050100 00100000 00
And then it returned a status indicating no error but 4096 bytes
residue (i.e., incorrect or undelivered data). This caused the
usb-storage driver to send the SCSI layer a result code of DID_ERROR
with no sense data.
> sd 0:0:0:0: [sda] Unhandled error code
> sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
> end_request: I/O error, dev sda, sector 44783
The DID_ERROR code caused the SCSI layer to display this error message.
> sd 0:0:0:0: [sda] Unhandled error code
> sd 0:0:0:0: [sda] Result: hostbyte=0x07 driverbyte=0x00
> end_request: I/O error, dev sda, sector 51823
I would have expected the READ to be retried, but in these two cases
it wasn't. The usbmon log contained five instances of this error
sequence; the other three were retried successfully. I don't know what
the difference was.
Alan Stern
Honza
Perhaps the time it took to complete.
I have a very old IDE disk connected to a USB box here, and some bad sectors take ages
to return. One thing I wanted to investigate is why the complete Linux system is frozen
for minutes when I "cp" one of these bad-sectors and then every thing is back to normal.
It's just an inserted external box. Swap system and everything is on an another healthy HD.
As if the USB controller actually locks the PCI bus, or the interrupts are off for a long
while. (Or is it the BKL?)
Do you have time stamps on these?
> Alan Stern
>
Boaz
> > I would have expected the READ to be retried, but in these two cases
> > it wasn't. The usbmon log contained five instances of this error
> > sequence; the other three were retried successfully. I don't know what
> > the difference was.
> >
>
> Perhaps the time it took to complete.
>
> I have a very old IDE disk connected to a USB box here, and some bad sectors take ages
> to return. One thing I wanted to investigate is why the complete Linux system is frozen
> for minutes when I "cp" one of these bad-sectors and then every thing is back to normal.
> It's just an inserted external box. Swap system and everything is on an another healthy HD.
> As if the USB controller actually locks the PCI bus, or the interrupts are off for a long
> while. (Or is it the BKL?)
>
> Do you have time stamps on these?
Yes. Each of the unsuccessful reads, whether retried or not, lasted
less than one millisecond. So that's probably not the reason.
On Tue, 24 Nov 2009, Jan Kara wrote:
> My naive guess would be that those non-retried reads were actually
> readahead. That's not retried if I remember correctly. Later, when we
> really needed the data, we sent another read request...
That would be my guess too. I don't know how to verify it, though.
If you're interested in pursuing this farther, I can show you how to
generate equivalent errors on demand using an emulated USB drive.
At this point it's not clear how much more one could learn by doing
this, however.
Alan Stern
Honza
While I agree it is useful information, I think that if the error messages
are going to be printed, you should *also* print that this is a NON FATAL
error and that it's going to be retried. It'd help diagnosing the path it's
following through the failure code IMHO as well as not making users
completely freak out like I did in my case. It is *not* particularly obvious
given the message printed to syslog what is going wrong or why.
Just my opinion,
Tim McGrath
I should have asked since I'm here at the moment - do you need any
more information out of the buggy USB enclosure at the moment, or can I work
on trying to fix/replace it now?
> I should have asked since I'm here at the moment - do you need any
> more information out of the buggy USB enclosure at the moment, or can I work
> on trying to fix/replace it now?
No, feel free to do anything with it :). Thanks for your help with
debugging this.
Honza
Thank *you* for giving me the initial reply. Without someone telling me they
were at least listening I may have given up entirely.
Tim McGrath
> > > > > Okay, very good. There remains the question of the disturbing error
> > > > > messages in the system log. Should they be supressed for FAILFAST
> > > > > requests?
> > > > I think it's useful they are there because ultimately, something really
> > > > went wrong and you should better investigate. BTW, "end_request: I/O error"
> > > > messages are in the log even for requests where we retried and succeeded...
That isn't true. Take a look at the dmesg log accompanying Tim's
usbmon log. Although there were 5 read errors in the usbmon log, there
were only 2 I/O error messages in dmesg, corresponding to the 2 reads
that weren't retried successfully.
Personally, I think it makes little sense to print error messages in
the system log for commands where retries are disallowed. Unless we go
ahead and print error messages for _all_ failures, including those
which are retried successfully.
Perhaps a good compromise would be to set the REQ_QUIET flag in
req->cmd_flags for readaheads. That would suppress the error messages
coming from the SCSI core.
> Yeah, we might make it more obvious that read failed and whether or not
> we are going to retry. Just technically it's not so simple because a
> different layer prints messages about errors (generic block layer) and
> different (scsi disk driver) decides what to do (retry, don't retry, ...).
Actually the retry decisions (or many of them) are made by the SCSI
core, and that's also where some of those error messages come from.
> > I should have asked since I'm here at the moment - do you need any
> > more information out of the buggy USB enclosure at the moment, or can I work
> > on trying to fix/replace it now?
> No, feel free to do anything with it :). Thanks for your help with
> debugging this.
To clarify, the enclosure isn't really very buggy. It _should_ have
carried out the failed commands, or if it had a valid reason for not
doing so then it _should_ have reported the reason. Regardless, the
errors that occurred were harmless because they went away when the
commands were retried. (Although if they weren't harmless, you
wouldn't be able to tell just from reading the system log...)
Alan Stern
Okay. Okay. Back up a moment here - Clarify a little. I have the filesystem
set to remount readonly on errors. I have not seen any filesystem
corruption or file corruption I could find. The filesystem *was* remounting
readonly under 2.6.31.5, but has not since .6 came out. (and I reformatted
and redid the entire backup under 2.6.31.6 without errors)
How do I know when it has generated an actual failure that was not
corrected?
How do I know when errors have been detected but they were corrected?
I'm guessing in the former, it'll remount ro, and in the latter it won't. Am
I correct?
I would like to save some money and not trash the usb enclosure... At the
same time, I don't want to use an enclosure that's trashing my data.
It is important to me to know exactly how the failure path operates. Please
explain to me what I will see happen. - Not knowing is driving me nuts.
Thank you,
Tim McGrath
Honza
> It is important to me to know exactly how the failure path operates. Please
> explain to me what I will see happen. - Not knowing is driving me nuts.
It goes like this. The computer sends a lot of READ commands to the
drive. (For all we know the same thing might happen with WRITEs, but
you didn't do any writing in the test data you sent.) Every now and
then the drive fails to carry out a READ, for no apparent reason.
Normally the computer then retries, and the READ succeeds the second
time. But of course, success isn't guaranteed. When the retry does
succeed, no error messages are printed in the log and everything
continues normally.
Occasionally the computer does not retry the READ -- in circumstances
where it doesn't really need the data (optimistic readahead). When
this happens, the failed READ does cause an error message to appear.
The same thing would happen if the attempted retries were to fail.
Whether or not this would result in lost or corrupted data, or
remounted readonly filesystems, depends on the kind of data being read.
Alan Stern
Hope to see you next time,
Tim McGrath