2009-11-13 05:09:07

by tmhikaru

[permalink] [raw]
Subject: Weird I/O errors with USB hard drive not remounting filesystem readonly

Hi. I already tried sending this email to the lkml a couple of days
ago. (With the subject re: 2.6.31.6) As I've gotten no response, and this
has been a problem for close to a month for me now, I've tried emailing
people (and other mailing lists) that may have a better clue of what's going
on here. I don't know what is going on here, so I've emailed the block
maintainer, ext4 filesystems list, usb mailing list, and scsi mailing list.
If I've reached you in error, and I have not actually sent this email to the
correct party, please inform me whom I should have sent this to. Thank you.

As I've had with the last few kernel releases in the 2.6.31.x
series, I'm still having a problem where I'm constantly getting seemingly
random I/O errors in dmesg output for my external usb hard drive. The thing
that worries me is that although my ext4 filesystem is configured to remount
readonly when problems occur, it is not in fact doing so. Does this mean the
error is transient, worked around, and I can ignore it, or ... what?

Specifically it is these messages I'm recieving whenever I do heavy duty
work with the drive that worries me:

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 79713943


Note that the sector number is never the same, and has never been the same
over a month's worth of I/O errors, but the unhandled error code result
always stays the same, though that also does not always show up.

In my attempts to determine if there's some sort of filesystem corruption
going on I haven't been able to find any problems - files that were changed
while the I/O errors seemed to be being generated are in fact perfect copies
according to md5sum.

I *really* need to know exactly what is going on here. Worst case scenario I
can think of is that the hard drive is going bad, but the symptoms don't
seem to bear that out. I need to know what the error messages - combined
with the the filesystem behavior (NOT remounting readonly) - mean.

I use the usb drive (a 250gb seagate using a rosewill external usb kit) to
backup two 120GB internal maxtors using rsync. These are all IDE hard
drives.

I would appreciate any tips on how I can determine if linux is working
around the problem silently on its own, or not.

The rest of this email includes dmesg output and various filesystem settings
I've set. Note in the dmesg output I plugged in and turned on the drive,
mounted it and poked around a bit, then unmounted it and ran my backup
script (Which e2fsck's it, mounts it, runs rsync to do the actual backup,
then unmounts it when it's done)


smartctl -H /dev/sda:
smartctl version 5.38 [i486-slackware-linux-gnu] Copyright (C) 2002-8 Bruce
Allen
Home page is http://smartmontools.sourceforge.net/

SMART Health Status: OK


fstab:

/dev/hda1 / ext4 defaults,barrier=1 1 1
/dev/hdb1 /home/tm/stuff ext4 defaults,user,barrier=1,noauto 0 1
/dev/sda1 /backup ext4 defaults,barrier=1,noauto 0 0
/swap none swap sw 0 0
/dev/cdrom /cdrom auto noauto,owner,ro 0 0
#/dev/fd0 /mnt/floppy auto noauto,owner 0 0
devpts /dev/pts devpts gid=5,mode=620 0 0
proc /proc proc defaults 0 0



tune2fs -l /dev/sda1:

tune2fs 1.41.8 (11-July-2009)
Filesystem volume name: <none>
Last mounted on: /backup
Filesystem UUID: f624b34a-80d4-422d-9c9e-4c3898b20d03
Filesystem magic number: 0xEF53
Filesystem revision #: 1 (dynamic)
Filesystem features: has_journal ext_attr resize_inode dir_index
filetype extent flex_bg sparse_super large_file huge_file uninit_bg
dir_nlink extra_isize
Filesystem flags: signed_directory_hash
Default mount options: (none)
Filesystem state: clean
Errors behavior: Remount read-only
Filesystem OS type: Linux
Inode count: 15269888
Block count: 61049000
Reserved block count: 0
Free blocks: 11536553
Free inodes: 14717189
First block: 0
Block size: 4096
Fragment size: 4096
Reserved GDT blocks: 1009
Blocks per group: 32768
Fragments per group: 32768
Inodes per group: 8192
Inode blocks per group: 512
Flex block group size: 16
Filesystem created: Wed Oct 14 00:19:20 2009
Last mount time: Thu Nov 12 02:27:48 2009
Last write time: Thu Nov 12 02:36:22 2009
Mount count: 6
Maximum mount count: 38
Last checked: Mon Nov 9 11:59:38 2009
Check interval: 15552000 (6 months)
Next check after: Sat May 8 12:59:38 2010
Lifetime writes: 204 GB
Reserved blocks uid: 0 (user root)
Reserved blocks gid: 0 (group root)
First inode: 11
Inode size: 256
Required extra isize: 28
Desired extra isize: 28
Journal inode: 8
Default directory hash: half_md4
Directory Hash Seed: 0a63a3e0-f270-41bd-8593-5fe644a69444
Journal backup: inode blocks


dmesg:

Linux version 2.6.31.6 ([email protected]) (gcc version 4.3.3 (GCC) ) #1 Tue Nov 10
22:41:09 EST 2009
KERNEL supported cpus:
Intel GenuineIntel
AMD AuthenticAMD
NSC Geode by NSC
Cyrix CyrixInstead
Centaur CentaurHauls
Transmeta GenuineTMx86
Transmeta TransmetaCPU
UMC UMC UMC UMC
BIOS-provided physical RAM map:
BIOS-e820: 0000000000000000 - 000000000009fc00 (usable)
BIOS-e820: 000000000009fc00 - 00000000000a0000 (reserved)
BIOS-e820: 00000000000e8000 - 00000000000ea000 (reserved)
BIOS-e820: 00000000000f0000 - 0000000000100000 (reserved)
BIOS-e820: 0000000000100000 - 000000005fff0000 (usable)
BIOS-e820: 000000005fff0000 - 000000005fff8000 (ACPI data)
BIOS-e820: 000000005fff8000 - 0000000060000000 (ACPI NVS)
BIOS-e820: 00000000fec00000 - 00000000fec01000 (reserved)
BIOS-e820: 00000000fee00000 - 00000000fee01000 (reserved)
BIOS-e820: 00000000ffee0000 - 00000000fff00000 (reserved)
BIOS-e820: 00000000fffc0000 - 0000000100000000 (reserved)
DMI 2.3 present.
last_pfn = 0x5fff0 max_arch_pfn = 0x100000
MTRR default type: uncachable
MTRR fixed ranges enabled:
00000-9FFFF write-back
A0000-EFFFF uncachable
F0000-FFFFF write-protect
MTRR variable ranges enabled:
0 base 000000000 mask FC0000000 write-back
1 base 040000000 mask FE0000000 write-back
2 disabled
3 disabled
4 disabled
5 disabled
6 disabled
7 base 0D0000000 mask FF8000000 write-combining
initial memory mapped : 0 - 01800000
init_memory_mapping: 0000000000000000-00000000377fe000
0000000000 - 0000400000 page 4k
0000400000 - 0037400000 page 2M
0037400000 - 00377fe000 page 4k
kernel direct mapping tables up to 377fe000 @ 7000-c000
ACPI: RSDP 000fa260 00014 (v00 AMI )
ACPI: RSDT 5fff0000 0002C (v01 AMIINT SiS740XX 00001000 MSFT 0100000B)
ACPI: FACP 5fff0030 00081 (v01 AMIINT SiS740XX 00000011 MSFT 0100000B)
ACPI: DSDT 5fff0110 034D2 (v01 SiS 740 00000100 MSFT 0100000D)
ACPI: FACS 5fff8000 00040
ACPI: APIC 5fff00c0 00050 (v01 AMIINT SiS740XX 00001000 MSFT 0100000B)
ACPI: Local APIC address 0xfee00000
647MB HIGHMEM available.
887MB LOWMEM available.
mapped low ram: 0 - 377fe000
low ram: 0 - 377fe000
node 0 low ram: 00000000 - 377fe000
node 0 bootmap 00008000 - 0000ef00
(6 early reservations) ==> bootmem [0000000000 - 00377fe000]
#0 [0000000000 - 0000001000] BIOS data page ==> [0000000000 -
#0000001000]
#1 [0001000000 - 0001605bd8] TEXT DATA BSS ==> [0001000000 -
#0001605bd8]
#2 [000009fc00 - 0000100000] BIOS reserved ==> [000009fc00 -
#0000100000]
#3 [0001606000 - 000160c0dc] BRK ==> [0001606000 -
#000160c0dc]
#4 [0000007000 - 0000008000] PGTABLE ==> [0000007000 -
#0000008000]
#5 [0000008000 - 000000f000] BOOTMAP ==> [0000008000 -
#000000f000]
Zone PFN ranges:
DMA 0x00000000 -> 0x00001000
Normal 0x00001000 -> 0x000377fe
HighMem 0x000377fe -> 0x0005fff0
Movable zone start PFN for each node
early_node_map[2] active PFN ranges
0: 0x00000000 -> 0x0000009f
0: 0x00000100 -> 0x0005fff0
On node 0 totalpages: 393103
free_area_init_node: node 0, pgdat c154b660, node_mem_map c160d000
DMA zone: 32 pages used for memmap
DMA zone: 0 pages reserved
DMA zone: 3967 pages, LIFO batch:0
Normal zone: 1744 pages used for memmap
Normal zone: 221486 pages, LIFO batch:31
HighMem zone: 1296 pages used for memmap
HighMem zone: 164578 pages, LIFO batch:31
Using APIC driver default
ACPI: PM-Timer IO Port: 0x808
ACPI: Local APIC address 0xfee00000
ACPI: LAPIC (acpi_id[0x01] lapic_id[0x00] enabled)
ACPI: LAPIC_NMI (acpi_id[0x01] high edge lint[0x1])
ACPI: IOAPIC (id[0x02] address[0xfec00000] gsi_base[0])
IOAPIC[0]: apic_id 2, version 17, address 0xfec00000, GSI 0-23
ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 high edge)
ACPI: IRQ0 used by override.
ACPI: IRQ2 used by override.
ACPI: IRQ9 used by override.
Enabling APIC mode: Flat. Using 1 I/O APICs
Using ACPI (MADT) for SMP configuration information
nr_irqs_gsi: 24
PM: Registered nosave memory: 000000000009f000 - 00000000000a0000
PM: Registered nosave memory: 00000000000a0000 - 00000000000e8000
PM: Registered nosave memory: 00000000000e8000 - 00000000000ea000
PM: Registered nosave memory: 00000000000ea000 - 00000000000f0000
PM: Registered nosave memory: 00000000000f0000 - 0000000000100000
Allocating PCI resources starting at 60000000 (gap: 60000000:9ec00000)
Built 1 zonelists in Zone order, mobility grouping on. Total pages: 390031
Kernel command line: BOOT_IMAGE=Linux ro root=301 vt.default_utf8=0
PID hash table entries: 4096 (order: 12, 16384 bytes)
Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
Enabling fast FPU save and restore... done.
Enabling unmasked SIMD FPU exception support... done.
Initializing CPU#0
Initializing HighMem for node 0 (000377fe:0005fff0)
Memory: 1552220k/1572800k available (4017k kernel code, 19312k reserved,
1431k data, 376k init, 663496k highmem)
virtual kernel memory layout:
fixmap : 0xfffa4000 - 0xfffff000 ( 364 kB)
pkmap : 0xff800000 - 0xffc00000 (4096 kB)
vmalloc : 0xf7ffe000 - 0xff7fe000 ( 120 MB)
lowmem : 0xc0000000 - 0xf77fe000 ( 887 MB)
.init : 0xc1553000 - 0xc15b1000 ( 376 kB)
.data : 0xc13ec426 - 0xc1552128 (1431 kB)
.text : 0xc1000000 - 0xc13ec426 (4017 kB)
Checking if this processor honours the WP bit even in supervisor mode...Ok.
SLUB: Genslabs=13, HWalign=32, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
NR_IRQS:288
Fast TSC calibration using PIT
Detected 2083.004 MHz processor.
Console: colour VGA+ 80x25
console [tty0] enabled
Calibrating delay loop (skipped), value calculated using timer frequency..
4166.00 BogoMIPS (lpj=2083004)
Security Framework initialized
Mount-cache hash table entries: 512
CPU: CLK_CTL MSR was 6003d22f. Reprogramming to 2003d22f
CPU: L1 I Cache: 64K (64 bytes/line), D cache 64K (64 bytes/line)
CPU: L2 Cache: 512K (64 bytes/line)
mce: CPU supports 4 MCE banks
Performance Counters: AMD PMU driver.
... version: 0
... bit width: 48
... generic counters: 4
... value mask: 0000ffffffffffff
... max period: 00007fffffffffff
... fixed-purpose counters: 0
... counter mask: 000000000000000f
CPU: AMD Athlon(tm) XP 2800+ stepping 00
Checking 'hlt' instruction... OK.
ACPI: Core revision 20090521
..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
xor: automatically using best checksumming function: pIII_sse
pIII_sse : 2740.000 MB/sec
xor: using function: pIII_sse (2740.000 MB/sec)
NET: Registered protocol family 16
ACPI: bus type pci registered
PCI: PCI BIOS revision 2.10 entry at 0xfdb01, last bus=2
PCI: Using configuration type 1 for base access
bio: create slab <bio-0> at 0
ACPI: EC: Look up EC in DSDT
ACPI: Interpreter enabled
ACPI: (supports S0 S1 S4 S5)
ACPI: Using IOAPIC for interrupt routing
ACPI: Power Resource [URP1] (off)
ACPI: Power Resource [URP2] (off)
ACPI: Power Resource [FDDP] (off)
ACPI: Power Resource [LPTP] (off)
ACPI: No dock devices found.
ACPI: PCI Root Bridge [PCI0] (0000:00)
pci 0000:00:00.0: reg 10 32bit mmio: [0xd0000000-0xd7ffffff]
pci 0000:00:02.0: Enabling SiS 96x SMBus
pci 0000:00:02.1: reg 20 io port: [0xc00-0xc1f]
pci 0000:00:02.5: reg 20 io port: [0xff00-0xff0f]
pci 0000:00:03.0: reg 10 32bit mmio: [0xcfffe000-0xcfffefff]
pci 0000:00:03.1: reg 10 32bit mmio: [0xcffff000-0xcfffffff]
pci 0000:00:03.2: reg 10 32bit mmio: [0xcffdf000-0xcffdffff]
pci 0000:00:03.2: PME# supported from D0 D3hot D3cold
pci 0000:00:03.2: PME# disabled
pci 0000:00:04.0: reg 10 io port: [0xdc00-0xdcff]
pci 0000:00:04.0: reg 14 32bit mmio: [0xcfffd000-0xcfffdfff]
pci 0000:00:04.0: reg 30 32bit mmio: [0xcffa0000-0xcffbffff]
pci 0000:00:04.0: supports D1 D2
pci 0000:00:04.0: PME# supported from D0 D1 D2 D3hot D3cold
pci 0000:00:04.0: PME# disabled
pci 0000:00:0a.0: reg 10 io port: [0xd800-0xd8ff]
pci 0000:00:0a.0: reg 14 32bit mmio: [0xcfffcf00-0xcfffcfff]
pci 0000:00:0a.0: reg 30 32bit mmio: [0xcffe0000-0xcffeffff]
pci 0000:00:0a.0: supports D1 D2
pci 0000:00:0a.0: PME# supported from D0 D1 D2 D3hot D3cold
pci 0000:00:0a.0: PME# disabled
pci 0000:00:0c.0: reg 10 io port: [0xd400-0xd43f]
pci 0000:00:0c.0: supports D2
pci 0000:01:00.0: reg 10 64bit mmio: [0xb0000000-0xbfffffff]
pci 0000:01:00.0: reg 18 64bit mmio: [0xcfef0000-0xcfefffff]
pci 0000:01:00.0: reg 20 io port: [0xb800-0xb8ff]
pci 0000:01:00.0: reg 30 32bit mmio: [0xcfec0000-0xcfedffff]
pci 0000:01:00.0: supports D1 D2
pci 0000:01:00.1: reg 10 64bit mmio: [0xcfee0000-0xcfeeffff]
pci 0000:01:00.1: supports D1 D2
pci 0000:00:01.0: bridge io port: [0xb000-0xbfff]
pci 0000:00:01.0: bridge 32bit mmio: [0xcfd00000-0xcfefffff]
pci 0000:00:01.0: bridge 32bit mmio pref: [0xafa00000-0xcfbfffff]
pci_bus 0000:00: on NUMA node 0
ACPI: PCI Interrupt Routing Table [\_SB_.PCI0._PRT]
ACPI: PCI Interrupt Link [LNKA] (IRQs 3 4 5 7 10 *11 12 14 15)
ACPI: PCI Interrupt Link [LNKB] (IRQs 3 4 5 7 10 11 12 14 15) *0, disabled.
ACPI: PCI Interrupt Link [LNKC] (IRQs 3 4 *5 7 10 11 12 14 15)
ACPI: PCI Interrupt Link [LNKD] (IRQs 3 4 *5 7 10 11 12 14 15)
ACPI: PCI Interrupt Link [LNKE] (IRQs 3 4 5 7 *10 11 12 14 15)
ACPI: PCI Interrupt Link [LNKF] (IRQs 3 4 *5 7 10 11 12 14 15)
ACPI: PCI Interrupt Link [LNKG] (IRQs 3 4 5 7 10 11 12 14 15) *0, disabled.
ACPI: PCI Interrupt Link [LNKH] (IRQs 3 4 5 7 *10 11 12 14 15)
SCSI subsystem initialized
libata version 3.00 loaded.
usbcore: registered new interface driver usbfs
usbcore: registered new interface driver hub
usbcore: registered new device driver usb
raid6: int32x1 898 MB/s
raid6: int32x2 914 MB/s
raid6: int32x4 722 MB/s
raid6: int32x8 640 MB/s
raid6: mmxx1 1675 MB/s
raid6: mmxx2 3050 MB/s
raid6: sse1x1 1613 MB/s
raid6: sse1x2 2609 MB/s
raid6: using algorithm sse1x2 (2609 MB/s)
PCI: Using ACPI for IRQ routing
pnp: PnP ACPI init
ACPI: bus type pnp registered
pnp: PnP ACPI: found 12 devices
ACPI: ACPI bus type pnp unregistered
system 00:01: ioport range 0x290-0x297 has been reserved
system 00:01: ioport range 0x480-0x48f has been reserved
system 00:01: ioport range 0x4d0-0x4d1 has been reserved
system 00:01: ioport range 0xc00-0xc1f has been reserved
system 00:01: ioport range 0x3f0-0x3f1 has been reserved
system 00:01: iomem range 0xfee00000-0xfeefffff could not be reserved
pci 0000:00:01.0: PCI bridge, secondary bus 0000:01
pci 0000:00:01.0: IO window: 0xb000-0xbfff
pci 0000:00:01.0: MEM window: 0xcfd00000-0xcfefffff
pci 0000:00:01.0: PREFETCH window: 0xafa00000-0xcfbfffff
pci_bus 0000:00: resource 0 io: [0x00-0xffff]
pci_bus 0000:00: resource 1 mem: [0x000000-0xffffffff]
pci_bus 0000:01: resource 0 io: [0xb000-0xbfff]
pci_bus 0000:01: resource 1 mem: [0xcfd00000-0xcfefffff]
pci_bus 0000:01: resource 2 pref mem [0xafa00000-0xcfbfffff]
NET: Registered protocol family 2
IP route cache hash table entries: 32768 (order: 5, 131072 bytes)
TCP established hash table entries: 131072 (order: 8, 1048576 bytes)
TCP bind hash table entries: 65536 (order: 6, 262144 bytes)
TCP: Hash tables configured (established 131072 bind 65536)
TCP reno registered
NET: Registered protocol family 1
highmem bounce pool size: 64 pages
VFS: Disk quotas dquot_6.5.2
Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
ROMFS MTD (C) 2007 Red Hat, Inc.
msgmni has been set to 1737
alg: No test for cipher_null (cipher_null-generic)
alg: No test for ecb(cipher_null) (ecb-cipher_null)
alg: No test for digest_null (digest_null-generic)
alg: No test for compress_null (compress_null-generic)
alg: No test for fcrypt (fcrypt-generic)
alg: No test for stdrng (krng)
async_tx: api initialized (async)
Block layer SCSI generic (bsg) driver version 0.4 loaded (major 254)
io scheduler noop registered
io scheduler anticipatory registered
io scheduler deadline registered
io scheduler cfq registered (default)
pci 0000:01:00.0: Boot video device
pci_hotplug: PCI Hot Plug PCI Core version: 0.5
isapnp: Scanning for PnP cards...
isapnp: No Plug & Play device found
Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
Switched to NOHz mode on CPU #0
serial8250: ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
serial8250: ttyS1 at I/O 0x2f8 (irq = 3) is a 16550A
00:09: ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
00:0a: ttyS1 at I/O 0x2f8 (irq = 3) is a 16550A
Floppy drive(s): fd0 is 1.44M
FDC 0 is a post-1991 82077
brd: module loaded
loop: module loaded
input: Macintosh mouse button emulation as /devices/virtual/input/input0
Uniform Multi-Platform E-IDE driver
sis5513 0000:00:02.5: SiS 962/963 MuTIOL IDE UDMA133 controller
sis5513 0000:00:02.5: IDE controller (0x1039:0x5513 rev 0x00)
sis5513 0000:00:02.5: not 100% native mode: will probe irqs later
ide0: BM-DMA at 0xff00-0xff07
ide1: BM-DMA at 0xff08-0xff0f
Probing IDE interface ide0...
hda: Maxtor 6Y120L0, ATA DISK drive
hdb: Maxtor 6Y120P0, ATA DISK drive
hda: host max PIO4 wanted PIO255(auto-tune) selected PIO4
hda: UDMA/133 mode selected
hdb: host max PIO4 wanted PIO255(auto-tune) selected PIO4
hdb: UDMA/133 mode selected
Probing IDE interface ide1...
hdc: HL-DT-STDVD-RAM GSA-H55N, ATAPI CD/DVD-ROM drive
hdc: host max PIO4 wanted PIO255(auto-tune) selected PIO4
hdc: UDMA/66 mode selected
ide0 at 0x1f0-0x1f7,0x3f6 on irq 14
ide1 at 0x170-0x177,0x376 on irq 15
ide-gd driver 1.18
hda: max request size: 128KiB
hda: 240121728 sectors (122942 MB) w/2048KiB Cache, CHS=65535/16/63
hda: cache flushes supported
hda: hda1
hdb: max request size: 128KiB
hdb: 240121728 sectors (122942 MB) w/7936KiB Cache, CHS=65535/16/63
hdb: cache flushes supported
hdb: hdb1
ide-cd driver 5.00
ide-cd: hdc: ATAPI 48X DVD-ROM DVD-R/RAM CD-R/RW drive, 2048kB Cache
Uniform CD-ROM driver Revision: 3.20
PNP: PS/2 Controller [PNP0303:PS2K,PNP0f03:PS2M] at 0x60,0x64 irq 1,12
serio: i8042 KBD port at 0x60,0x64 irq 1
serio: i8042 AUX port at 0x60,0x64 irq 12
mice: PS/2 mouse device common for all mice
md: linear personality registered for level -1
md: raid0 personality registered for level 0
md: raid1 personality registered for level 1
md: raid10 personality registered for level 10
md: raid6 personality registered for level 6
md: raid5 personality registered for level 5
md: raid4 personality registered for level 4
md: multipath personality registered for level -4
device-mapper: ioctl: 4.15.0-ioctl (2009-04-01) initialised:
[email protected]
cpuidle: using governor ladder
cpuidle: using governor menu
TCP cubic registered
Initializing XFRM netlink socket
NET: Registered protocol family 17
Using IPI Shortcut mode
input: AT Translated Set 2 keyboard as
/devices/platform/i8042/serio0/input/input1
md: Waiting for all devices to be available before autodetect
md: If you don't use raid, use raid=noautodetect
md: Autodetecting RAID arrays.
md: Scanned 0 and added 0 devices.
md: autorun ...
md: ... autorun DONE.
EXT4-fs (hda1): barriers enabled
kjournald2 starting: pid 1091, dev hda1:8, commit interval 5 seconds
EXT4-fs (hda1): delayed allocation enabled
EXT4-fs: file extents enabled
EXT4-fs: mballoc enabled
EXT4-fs (hda1): mounted filesystem with ordered data mode
VFS: Mounted root (ext4 filesystem) readonly on device 3:1.
Freeing unused kernel memory: 376k freed
input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input2
ACPI: Power Button [PWRF]
input: Power Button as
/devices/LNXSYSTM:00/device:00/PNP0C0C:00/input/input3
ACPI: Power Button [PWRB]
input: Sleep Button as
/devices/LNXSYSTM:00/device:00/PNP0C0E:00/input/input4
ACPI: Sleep Button [SLPB]
sis900.c: v1.08.10 Apr. 2 2006
sis900 0000:00:04.0: PCI INT A -> GSI 19 (level, low) -> IRQ 19
0000:00:04.0: VIA 6103 PHY transceiver found at address 1.
0000:00:04.0: Using transceiver found at address 1 as default
eth0: SiS 900 PCI Fast Ethernet at 0xdc00, IRQ 19, 00:19:21:9b:5b:e7
ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
ehci_hcd 0000:00:03.2: PCI INT D -> GSI 23 (level, low) -> IRQ 23
ehci_hcd 0000:00:03.2: EHCI Host Controller
ehci_hcd 0000:00:03.2: new USB bus registered, assigned bus number 1
ehci_hcd 0000:00:03.2: cache line size of 64 is not supported
ehci_hcd 0000:00:03.2: irq 23, io mem 0xcffdf000
8139too Fast Ethernet driver 0.9.28
ehci_hcd 0000:00:03.2: USB 2.0 started, EHCI 1.00
usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
usb usb1: Product: EHCI Host Controller
usb usb1: Manufacturer: Linux 2.6.31.6 ehci_hcd
usb usb1: SerialNumber: 0000:00:03.2
usb usb1: configuration #1 chosen from 1 choice
hub 1-0:1.0: USB hub found
hub 1-0:1.0: 6 ports detected
8139too 0000:00:0a.0: PCI INT A -> GSI 18 (level, low) -> IRQ 18
eth1: RealTek RTL8139 at 0xd800, 00:e0:29:9b:1a:15, IRQ 18
processor LNXCPU:00: registered as cooling_device0
rtc_cmos 00:03: RTC can wake from S4
rtc_cmos 00:03: rtc core: registered rtc_cmos as rtc0
rtc0: alarms up to one month, 114 bytes nvram
input: ImExPS/2 Generic Explorer Mouse as
/devices/platform/i8042/serio1/input/input5
Linux agpgart interface v0.103
agpgart-sis 0000:00:00.0: SiS chipset [1039/0746]
agpgart-sis 0000:00:00.0: AGP aperture is 128M @ 0xd0000000
sis96x_smbus 0000:00:02.1: SiS96x SMBus base address: 0x0c00
ACPI: I/O resource 0000:00:02.1 [0xc00-0xc1f] conflicts with ACPI region
SMRG [0xc00-0xc1f]
ACPI: If an ACPI driver is available for this device, you should use it
instead of the native driver
shpchp: Standard Hot Plug PCI Controller Driver version: 0.4
parport_pc 00:0b: reported by Plug and Play ACPI
parport0: PC-style at 0x378 (0x778), irq 7 [PCSPP,TRISTATE]
ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
ohci_hcd 0000:00:03.0: PCI INT A -> GSI 20 (level, low) -> IRQ 20
ohci_hcd 0000:00:03.0: OHCI Host Controller
ohci_hcd 0000:00:03.0: new USB bus registered, assigned bus number 2
ohci_hcd 0000:00:03.0: irq 20, io mem 0xcfffe000
usb usb2: New USB device found, idVendor=1d6b, idProduct=0001
usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
usb usb2: Product: OHCI Host Controller
usb usb2: Manufacturer: Linux 2.6.31.6 ohci_hcd
usb usb2: SerialNumber: 0000:00:03.0
usb usb2: configuration #1 chosen from 1 choice
hub 2-0:1.0: USB hub found
hub 2-0:1.0: 3 ports detected
ohci_hcd 0000:00:03.1: PCI INT B -> GSI 21 (level, low) -> IRQ 21
ohci_hcd 0000:00:03.1: OHCI Host Controller
ohci_hcd 0000:00:03.1: new USB bus registered, assigned bus number 3
ohci_hcd 0000:00:03.1: irq 21, io mem 0xcffff000
usb usb3: New USB device found, idVendor=1d6b, idProduct=0001
usb usb3: New USB device strings: Mfr=3, Product=2, SerialNumber=1
usb usb3: Product: OHCI Host Controller
usb usb3: Manufacturer: Linux 2.6.31.6 ohci_hcd
usb usb3: SerialNumber: 0000:00:03.1
usb usb3: configuration #1 chosen from 1 choice
hub 3-0:1.0: USB hub found
hub 3-0:1.0: 3 ports detected
ENS1371 0000:00:0c.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16
ppdev: user-space parallel port driver
usb 3-3: new low speed USB device using ohci_hcd and address 2
usb 3-3: New USB device found, idVendor=0428, idProduct=4001
usb 3-3: New USB device strings: Mfr=1, Product=2, SerialNumber=0
usb 3-3: Product: GamePad Pro USB
usb 3-3: Manufacturer: Gravis
usb 3-3: configuration #1 chosen from 1 choice
fuse init (API version 7.12)
EXT4-fs (hda1): internal journal on hda1:8
hda: UDMA/133 mode selected
hdb: UDMA/133 mode selected
hdc: UDMA/66 mode selected
usbcore: registered new interface driver hiddev
input: Gravis GamePad Pro USB as
/devices/pci0000:00/0000:00:03.1/usb3/3-3/3-3:1.0/input/input6
generic-usb 0003:0428:4001.0001: input,hidraw0: USB HID v1.00 Gamepad
/[Gravis GamePad Pro USB ] on usb-0000:00:03.1-3/input0
usbcore: registered new interface driver usbhid
usbhid: v2.6:USB HID core driver
PPP generic driver version 2.4.2
[drm] Initialized drm 1.1.0 20060810
pci 0000:01:00.0: PCI INT A -> GSI 16 (level, low) -> IRQ 16
[drm] Initialized radeon 1.31.0 20080528 for 0000:01:00.0 on minor 0
uhci_hcd: USB Universal Host Controller Interface driver
input: PC Speaker as /devices/platform/pcspkr/input/input7
it87: Found IT8705F chip at 0x290, revision 3
Adding 2097144k swap on /swap. Priority:-1 extents:3 across:2793464k
eth1: link up, 100Mbps, full-duplex, lpa 0x45E1
NET: Registered protocol family 10
lo: Disabled Privacy Extensions
eth1: no IPv6 routers present
warning: quid' uses 32-bit capabilities (legacy support in use)
u32 classifier
Actions configured
eth0: Media Link On 100mbps full-duplex
PPP BSD Compression module registered
ip_tables: (C) 2000-2006 Netfilter Core Team
nf_conntrack version 0.5.0 (16384 buckets, 65536 max)
CONFIG_NF_CT_ACCT is deprecated and will be removed soon. Please use
nf_conntrack.acct=1 kernel parameter, acct=1 nf_conntrack module option or
sysctl net.netfilter.nf_conntrack_acct=1 to enable it.
eth0: no IPv6 routers present
agpgart-sis 0000:00:00.0: AGP 3.0 bridge
agpgart-sis 0000:00:00.0: putting AGP V3 device at 0000:00:00.0 into 4x mode
agpgart-sis 0000:00:00.0: SiS delay workaround: giving bridge time to
recover
agpgart-sis 0000:00:00.0: putting AGP V3 device at 0000:01:00.0 into 4x mode
[drm] Setting GART location based on new memory map
[drm] Loading R500 Microcode
[drm] Num pipes: 1
[drm] writeback test succeeded in 1 usecs
[drm] Num pipes: 1
mtrr: MTRR 2 not used
agpgart-sis 0000:00:00.0: AGP 3.0 bridge
agpgart-sis 0000:00:00.0: putting AGP V3 device at 0000:00:00.0 into 4x mode
agpgart-sis 0000:00:00.0: SiS delay workaround: giving bridge time to
recover
agpgart-sis 0000:00:00.0: putting AGP V3 device at 0000:01:00.0 into 4x mode
[drm] Setting GART location based on new memory map
[drm] Loading R500 Microcode
[drm] Num pipes: 1
[drm] writeback test succeeded in 1 usecs
usb 1-4: new high speed USB device using ehci_hcd and address 3
usb 1-4: New USB device found, idVendor=067b, idProduct=2506
usb 1-4: New USB device strings: Mfr=1, Product=2, SerialNumber=3
usb 1-4: Product: Mass Storage Device
usb 1-4: Manufacturer: Prolific Technology Inc.
usb 1-4: SerialNumber: 0
usb 1-4: 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:
sd 0:0:0:0: Attached scsi generic sg0 type 0
sda1
sd 0:0:0:0: [sda] Assuming drive cache: write through
sd 0:0:0:0: [sda] Attached SCSI disk
EXT4-fs (sda1): barriers enabled
kjournald2 starting: pid 3390, 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
EXT4-fs: mballoc: 5780 blocks 36 reqs (13 success)
EXT4-fs: mballoc: 28 extents scanned, 2 goal hits, 26 2^N hits, 0 breaks, 0
lost
EXT4-fs: mballoc: 113 generated and it took 1911664
EXT4-fs: mballoc: 3961 preallocated, 3449 discarded
EXT4-fs (sda1): barriers enabled
kjournald2 starting: pid 3411, 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 79713943
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 79714231
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 61431
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 4223935
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 8417519
EXT4-fs (hdb1): barriers enabled
kjournald2 starting: pid 3539, dev hdb1:8, commit interval 5 seconds
EXT4-fs (hdb1): internal journal on hdb1:8
EXT4-fs (hdb1): delayed allocation enabled
EXT4-fs: file extents enabled
EXT4-fs: mballoc enabled
EXT4-fs (hdb1): mounted filesystem with ordered data mode
EXT4-fs: mballoc: 0 blocks 0 reqs (0 success)
EXT4-fs: mballoc: 0 extents scanned, 0 goal hits, 0 2^N hits, 0 breaks, 0
lost
EXT4-fs: mballoc: 0 generated and it took 0
EXT4-fs: mballoc: 0 preallocated, 0 discarded
EXT4-fs: mballoc: 452074 blocks 31860 reqs (29968 success)
EXT4-fs: mballoc: 2099 extents scanned, 263 goal hits, 2028 2^N hits, 0
breaks, 0 lost
EXT4-fs: mballoc: 1208 generated and it took 19874212
EXT4-fs: mballoc: 318579 preallocated, 48300 discarded


2009-11-19 16:07:00

by Jan Kara

[permalink] [raw]
Subject: Re: Weird I/O errors with USB hard drive not remounting filesystem readonly

Hi,

> Hi. I already tried sending this email to the lkml a couple of days
> ago. (With the subject re: 2.6.31.6) As I've gotten no response, and this
> has been a problem for close to a month for me now, I've tried emailing
> people (and other mailing lists) that may have a better clue of what's going
> on here. I don't know what is going on here, so I've emailed the block
> maintainer, ext4 filesystems list, usb mailing list, and scsi mailing list.
> If I've reached you in error, and I have not actually sent this email to the
> correct party, please inform me whom I should have sent this to. Thank you.
>
> As I've had with the last few kernel releases in the 2.6.31.x
> series, I'm still having a problem where I'm constantly getting seemingly
> random I/O errors in dmesg output for my external usb hard drive. The thing
> that worries me is that although my ext4 filesystem is configured to remount
> readonly when problems occur, it is not in fact doing so. Does this mean the
> error is transient, worked around, and I can ignore it, or ... what?
>
> Specifically it is these messages I'm recieving whenever I do heavy duty
> work with the drive that worries me:
>
> 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 79713943
Well, my external hard drive does strange things when my USB port
isn't able to give it enough power (probably flaky USB controller on the
MB - OTOH I don't know why it sucks any power really since the drive has
external power supply anyway). Plugging into a different USB port solved
the problems for me.
Anyway, for some reason the IO error did not get up to buffer layer
but ended up in the block layer. Probably because bi_end_io function did
not reported it properly. Maybe you could debug that by adding a debug
printk into several places: e.g. to fs/bio.c:bio_endio(),
fs/buffer.c:end_bio_bh_io_sync(), fs/mpage.c:mpage_end_io_write(),
fs/mpage.c:mpage_end_io_read(), fs/ext4/extents.c:bi_complete() and see
whether 'error' is != 0 there and if yes, what it is.

> Note that the sector number is never the same, and has never been the same
> over a month's worth of I/O errors, but the unhandled error code result
> always stays the same, though that also does not always show up.
>
> In my attempts to determine if there's some sort of filesystem corruption
> going on I haven't been able to find any problems - files that were changed
> while the I/O errors seemed to be being generated are in fact perfect copies
> according to md5sum.
>
> I *really* need to know exactly what is going on here. Worst case scenario I
> can think of is that the hard drive is going bad, but the symptoms don't
> seem to bear that out. I need to know what the error messages - combined
> with the the filesystem behavior (NOT remounting readonly) - mean.
>
> I use the usb drive (a 250gb seagate using a rosewill external usb kit) to
> backup two 120GB internal maxtors using rsync. These are all IDE hard
> drives.
>
> I would appreciate any tips on how I can determine if linux is working
> around the problem silently on its own, or not.
From the

> The rest of this email includes dmesg output and various filesystem settings
> I've set. Note in the dmesg output I plugged in and turned on the drive,
> mounted it and poked around a bit, then unmounted it and ran my backup
> script (Which e2fsck's it, mounts it, runs rsync to do the actual backup,
> then unmounts it when it's done)
...
> EXT4-fs (sda1): barriers enabled
> kjournald2 starting: pid 3390, 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
> EXT4-fs: mballoc: 5780 blocks 36 reqs (13 success)
> EXT4-fs: mballoc: 28 extents scanned, 2 goal hits, 26 2^N hits, 0 breaks, 0
> lost
> EXT4-fs: mballoc: 113 generated and it took 1911664
> EXT4-fs: mballoc: 3961 preallocated, 3449 discarded
> EXT4-fs (sda1): barriers enabled
> kjournald2 starting: pid 3411, 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 79713943
> 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 79714231
> 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 61431
> 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 4223935
> 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 8417519

Honza
--
Jan Kara <[email protected]>
SuSE CR Labs

2009-11-23 08:17:32

by tmhikaru

[permalink] [raw]
Subject: Re: Weird I/O errors with USB hard drive not remounting filesystem readonly

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.

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


Attachments:
(No filename) (1.43 kB)
diskstats (8.38 kB)
diskstats2 (8.48 kB)
diskstats3 (8.48 kB)
Download all attachments

2009-11-23 10:54:35

by Jan Kara

[permalink] [raw]
Subject: Re: Weird I/O errors with USB hard drive not remounting filesystem readonly

Hi,

On Mon 23-11-09 03:09:19, [email protected] 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 <[email protected]>
SUSE Labs, CR

2009-11-23 15:06:03

by Alan Stern

[permalink] [raw]
Subject: Re: Weird I/O errors with USB hard drive not remounting filesystem readonly

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.

Alan Stern

2009-11-23 16:09:14

by Jan Kara

[permalink] [raw]
Subject: Re: Weird I/O errors with USB hard drive not remounting filesystem readonly

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 ;).

Honza
--
Jan Kara <[email protected]>
SUSE Labs, CR

2009-11-23 18:20:26

by Alan Stern

[permalink] [raw]
Subject: Re: Weird I/O errors with USB hard drive not remounting filesystem readonly

On Mon, 23 Nov 2009, Jan Kara wrote:

> 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


2009-11-23 18:54:50

by Jan Kara

[permalink] [raw]
Subject: Re: Weird I/O errors with USB hard drive not remounting filesystem readonly

On Mon 23-11-09 13:20:26, Alan Stern wrote:
> On Mon, 23 Nov 2009, Jan Kara wrote:
>
> > 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.
Ah, OK. The problem manifests itself as an error in SATA communication
(which in fact somehow happens over USB, but I don't really know the
details of mass storage over USB) so debugging USB would become actual only
if we found out it's really some bug in an usb stack. But so far the most
probable is just an error somewhere between the USB controller in the
enclosure and the drive itself. BTW: Is the data transferred over USB
checksummed?

Honza

2009-11-23 19:50:22

by tmhikaru

[permalink] [raw]
Subject: Re: Weird I/O errors with USB hard drive not remounting filesystem readonly

On Mon, Nov 23, 2009 at 07:54:50PM +0100, Jan Kara wrote:
> On Mon 23-11-09 13:20:26, Alan Stern wrote:
> > On Mon, 23 Nov 2009, Jan Kara wrote:
> >
> > > 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.
> Ah, OK. The problem manifests itself as an error in SATA communication
> (which in fact somehow happens over USB, but I don't really know the
> details of mass storage over USB) so debugging USB would become actual only
> if we found out it's really some bug in an usb stack. But so far the most
> probable is just an error somewhere between the USB controller in the
> enclosure and the drive itself. BTW: Is the data transferred over USB
> checksummed?
>
> Honza
Mind that this is an ide hard drive in a usb enclosure, not sata.
The error reported is bizzare. I don't know if I'll be able to get the
enclosure to cause the error on demand, but before I try supergluing it,
I'll try to do whatever I need to do with usbmon so we can get the error
that's actually happening so you can do whatever you need to do to track it
down :)

Tim McGrath

Subject: Re: Weird I/O errors with USB hard drive not remounting filesystem readonly

On Mon, Nov 23, 2009 at 02:50:22PM -0500, [email protected] wrote:
> On Mon, Nov 23, 2009 at 07:54:50PM +0100, Jan Kara wrote:
> > On Mon 23-11-09 13:20:26, Alan Stern wrote:
> > > On Mon, 23 Nov 2009, Jan Kara wrote:
> > >
> > > > 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.
> > Ah, OK. The problem manifests itself as an error in SATA communication
> > (which in fact somehow happens over USB, but I don't really know the
> > details of mass storage over USB) so debugging USB would become actual only
> > if we found out it's really some bug in an usb stack. But so far the most
> > probable is just an error somewhere between the USB controller in the
> > enclosure and the drive itself. BTW: Is the data transferred over USB
> > checksummed?
> >
> > Honza
> Mind that this is an ide hard drive in a usb enclosure, not sata.
> The error reported is bizzare. I don't know if I'll be able to get the
> enclosure to cause the error on demand, but before I try supergluing it,
> I'll try to do whatever I need to do with usbmon so we can get the error
> that's actually happening so you can do whatever you need to do to track it
> down :)
>
> Tim 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,

[email protected]:/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:

[email protected]:/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

2009-11-23 20:33:50

by Alan Stern

[permalink] [raw]
Subject: Re: Weird I/O errors with USB hard drive not remounting filesystem readonly

On Mon, 23 Nov 2009 [email protected] wrote:

> 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,
>
> [email protected]:/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:
>
> [email protected]:/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


Subject: Re: Weird I/O errors with USB hard drive not remounting filesystem readonly

On Mon, Nov 23, 2009 at 03:33:56PM -0500, Alan Stern wrote:
> On Mon, 23 Nov 2009 [email protected] wrote:
>
> > 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,
> >
> > [email protected]:/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:
> >
> > [email protected]:/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

2009-11-24 17:16:17

by Alan Stern

[permalink] [raw]
Subject: Re: Weird I/O errors with USB hard drive not remounting filesystem readonly

On Mon, 23 Nov 2009 [email protected] wrote:

> 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


2009-11-24 17:47:12

by Boaz Harrosh

[permalink] [raw]
Subject: Re: Weird I/O errors with USB hard drive not remounting filesystem readonly

On 11/24/2009 07:16 PM, Alan Stern wrote:
> On Mon, 23 Nov 2009 [email protected] wrote:
>
>> 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.
>

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

2009-11-24 18:00:38

by Jan Kara

[permalink] [raw]
Subject: Re: Weird I/O errors with USB hard drive not remounting filesystem readonly

On Tue 24-11-09 12:16:17, Alan Stern wrote:
> On Mon, 23 Nov 2009 [email protected] wrote:
>
> > 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.
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...

Honza

2009-11-24 19:28:34

by Alan Stern

[permalink] [raw]
Subject: Re: Weird I/O errors with USB hard drive not remounting filesystem readonly

On Tue, 24 Nov 2009, Boaz Harrosh wrote:

> > 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


2009-11-24 19:56:08

by Jan Kara

[permalink] [raw]
Subject: Re: Weird I/O errors with USB hard drive not remounting filesystem readonly

On Tue 24-11-09 14:28:35, Alan Stern wrote:
> 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.
After digging in block layer code, it's as we suspected:
In case of host error DID_ERROR (which is our case), scsi request is
retried iff it is not a FAILFAST request which is set if bio is doing
readahead... So this is explained and everything behaves as it should.
Thanks everybody involved :).

Honza

2009-11-24 20:13:01

by Alan Stern

[permalink] [raw]
Subject: Re: Weird I/O errors with USB hard drive not remounting filesystem readonly

On Tue, 24 Nov 2009, Jan Kara wrote:

> After digging in block layer code, it's as we suspected:
> In case of host error DID_ERROR (which is our case), scsi request is
> retried iff it is not a FAILFAST request which is set if bio is doing
> readahead... So this is explained and everything behaves as it should.
> Thanks everybody involved :).

Okay, very good. There remains the question of the disturbing error
messages in the system log. Should they be supressed for FAILFAST
requests?

Alan Stern


2009-11-24 20:39:44

by Jan Kara

[permalink] [raw]
Subject: Re: Weird I/O errors with USB hard drive not remounting filesystem readonly

On Tue 24-11-09 15:13:01, Alan Stern wrote:
> On Tue, 24 Nov 2009, Jan Kara wrote:
>
> > After digging in block layer code, it's as we suspected:
> > In case of host error DID_ERROR (which is our case), scsi request is
> > retried iff it is not a FAILFAST request which is set if bio is doing
> > readahead... So this is explained and everything behaves as it should.
> > Thanks everybody involved :).
>
> 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...

Honza

2009-11-24 21:50:44

by tmhikaru

[permalink] [raw]
Subject: Re: Weird I/O errors with USB hard drive not remounting filesystem readonly

On Tue, Nov 24, 2009 at 09:39:44PM +0100, Jan Kara wrote:
> On Tue 24-11-09 15:13:01, Alan Stern wrote:
> > On Tue, 24 Nov 2009, Jan Kara wrote:
> >
> > > After digging in block layer code, it's as we suspected:
> > > In case of host error DID_ERROR (which is our case), scsi request is
> > > retried iff it is not a FAILFAST request which is set if bio is doing
> > > readahead... So this is explained and everything behaves as it should.
> > > Thanks everybody involved :).
> >
> > 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...
>
> 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

2009-11-24 22:23:34

by tmhikaru

[permalink] [raw]
Subject: Re: Weird I/O errors with USB hard drive not remounting filesystem readonly

On Tue, Nov 24, 2009 at 04:50:44PM -0500, [email protected] wrote:
> On Tue, Nov 24, 2009 at 09:39:44PM +0100, Jan Kara wrote:
> > On Tue 24-11-09 15:13:01, Alan Stern wrote:
> > > On Tue, 24 Nov 2009, Jan Kara wrote:
> > >
> > > > After digging in block layer code, it's as we suspected:
> > > > In case of host error DID_ERROR (which is our case), scsi request is
> > > > retried iff it is not a FAILFAST request which is set if bio is doing
> > > > readahead... So this is explained and everything behaves as it should.
> > > > Thanks everybody involved :).
> > >
> > > 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...
> >
> > 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?

Tim McGrath

2009-11-25 08:42:41

by Jan Kara

[permalink] [raw]
Subject: Re: Weird I/O errors with USB hard drive not remounting filesystem readonly

On Tue 24-11-09 17:23:34, [email protected] wrote:
> On Tue, Nov 24, 2009 at 04:50:44PM -0500, [email protected] wrote:
> > On Tue, Nov 24, 2009 at 09:39:44PM +0100, Jan Kara wrote:
> > > On Tue 24-11-09 15:13:01, Alan Stern wrote:
> > > > On Tue, 24 Nov 2009, Jan Kara wrote:
> > > >
> > > > > After digging in block layer code, it's as we suspected:
> > > > > In case of host error DID_ERROR (which is our case), scsi request is
> > > > > retried iff it is not a FAILFAST request which is set if bio is doing
> > > > > readahead... So this is explained and everything behaves as it should.
> > > > > Thanks everybody involved :).
> > > >
> > > > 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...
> > >
> > > 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.
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, ...).

> 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

2009-11-25 09:38:05

by tmhikaru

[permalink] [raw]
Subject: Re: Weird I/O errors with USB hard drive not remounting filesystem readonly

On Wed, Nov 25, 2009 at 09:42:41AM +0100, Jan Kara wrote:
> No, feel free to do anything with it :). Thanks for your help with
> debugging this.

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

2009-11-25 16:10:48

by Alan Stern

[permalink] [raw]
Subject: Re: Weird I/O errors with USB hard drive not remounting filesystem readonly

On Wed, 25 Nov 2009, Jan Kara wrote:

> > > > > 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


2009-11-27 09:43:40

by tmhikaru

[permalink] [raw]
Subject: Re: Weird I/O errors with USB hard drive not remounting filesystem readonly

On Wed, Nov 25, 2009 at 11:10:48AM -0500, Alan Stern wrote:
> On Wed, 25 Nov 2009, Jan Kara wrote:
>
> > > > > > 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

2009-11-27 13:13:03

by Jan Kara

[permalink] [raw]
Subject: Re: Weird I/O errors with USB hard drive not remounting filesystem readonly

On Fri 27-11-09 04:43:39, [email protected] wrote:
> On Wed, Nov 25, 2009 at 11:10:48AM -0500, Alan Stern wrote:
> > On Wed, 25 Nov 2009, Jan Kara wrote:
> >
> > > > > > > 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?
So if just the file data cannot be read / written, you see messages
about IO errors in the log (as you see now), some application might get EIO
error but the filesystem will not be remounted. It gets remounted only if
some filesystem metadata cannot be read / written.
It's true that retrying commands usually succeeds but not always and thus
I find it possible that eventually it fails several times in a row so that
kernel just gives up and discards data block to write because it thinks it
has no way of writing it. So I personally would ask for a warranty exchange
of the enclosure...

Honza

2009-11-27 17:58:23

by Alan Stern

[permalink] [raw]
Subject: Re: Weird I/O errors with USB hard drive not remounting filesystem readonly

On Fri, 27 Nov 2009 [email protected] wrote:

> 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

2009-11-29 04:30:58

by tmhikaru

[permalink] [raw]
Subject: Re: Weird I/O errors with USB hard drive not remounting filesystem readonly

Thank you for the time and effort you had to spend on this, all of
you, I really appreciate all the hard work spent diagnosing my hardware
issues as well as explaining what the various error messages were coming
from.


Hope to see you next time,
Tim McGrath