Bug 465539

Some more information, that points at the kernel, indeed.

I narrowed the problem further to the first nash-resolveDevice command issued by mkinitrd, in my case:

echo nash-resolveDevice /dev/livre/test | /sbin/nash --forcequiet

Then, I performed a syscall binary search on it:

echo nash-resolveDevice /dev/livre/test | strace -f /sbin/nash --forcequiet 2>&1 | sed 436q | tail

Varying the 436, so as to figure out what the last syscall was before the problem.  strace would get a pipe error and kill the child process once its stderr was closed, so I knew exactly what the last known good syscall was, regardless of how long it took for the bad syscall to take effect.

Turns out that at 436, I would reliably not get a faulty array member, but at 437, I would quite often (but not absolutely every time) get it.  And the printed lines didn't vary, so I knew I was getting consistent results.

So, what were the last few lines?

open("/sys/block//sda/device/model", O_RDONLY) = 6
fcntl(6, F_GETFD)                       = 0
fcntl(6, F_SETFD, FD_CLOEXEC)           = 0
fstat(6, {st_mode=S_IFREG|0444, st_size=4096, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f128427c000
read(6, "00BEVT-60ZCT0   \n"..., 4096)  = 17
close(6)                                = 0 [line 436]
munmap(0x7f128427c000, 4096)            = 0 [line 437]

Up to this point, we're fine.  Now, the fact that we get an error at this point means the next syscall that strace would print (after issuing the call) is the one that triggers the error.  Here it is:

ioctl(5, SG_IO, {'S', SG_DXFER_FROM_DEV, cmd[6]=[12, 00, 00, 00, fe, 00], mx_sb_len=32, iovec_count=0, dxfer_len=254, timeout=5000, flags=0, data[254]=["\0\0\2\1\37\0\0\0WDC WD3200BEVT-60ZCT0   \0"...], status=00, masked_status=00, sb[0]=[], host_status=0, driver_status=0, resid=214, duration=1, info=0}) = 0


Anyhow, sda is (in this session) one of the external USB drives, and sda3 is the member of the md RAID1 array that fails after this syscall.  And here's what gets logged to /var/log/messages:

Oct  3 20:47:47 livre kernel: sd 0:0:0:0: [sda] Result: hostbyte=DID_ERROR drive
rbyte=DRIVER_OK,SUGGEST_RETRY
Oct  3 20:47:47 livre kernel: end_request: I/O error, dev sda, sector 156296262
Oct  3 20:47:47 livre kernel: end_request: I/O error, dev sda, sector 156296262
Oct  3 20:47:47 livre kernel: md: super_written gets error=-5, uptodate=0
Oct  3 20:47:47 livre kernel: raid1: Disk failure on sda3, disabling device.
Oct  3 20:47:47 livre kernel: raid1: Operation continuing on 2 devices.

Hmm...  This is a new 2.5" USB-powered disk, unlike the other 3.5" external enclosure, that's also USB but that draws power from a regular power outlet.

Right now I can't tell whether the error affects only this one (the order of the drives seems to change at every boot, so it's easy to be misled into believing it affects all disks), but I'll keep my eyes open.

Anyhow, this is looking like a kernel issue, and I don't quite see how mkinitrd could even work around it :-(  Reassigning, and marking as 'need info' for myself, so that I come back with more details about this specific disk, if it turns out to be the one that fails consistently, or something else if the failure varies over all 3 disks.

FTR, with tridge's scsi_io program (http://samba.org/~tridge/ctdb/utils/scsi_io/scsi_io.c), I managed to get sda to fail in a similar way with the usn (unit serial number) request.  It does return a serial number (unlike the other, older USB disk), but it fails afterwards.

That said, usn is not quite the same kind of request.  The exact syscall is:

ioctl(3, SG_IO, {'S', SG_DXFER_FROM_DEV, cmd[6]=[12, 01, 80, 00, ff, 00], mx_sb_len=32, iovec_count=0, dxfer_len=255, timeout=5000, flags=0, data[255]=["\0\200\0\f152D20329000\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...], status=00, masked_status=00, sb[0]=[], host_status=0, driver_status=0, resid=239, duration=2, info=0}) = 0

and identical errors get logged to /var/log/messages.

The other disks don't respond the same way (as in demanding a retry for the next operation).  So it's something specific to this particular device.  Ugh...  Any suggestions?

http://bugzilla.kernel.org/show_bug.cgi?id=9638 might be in some way related (just because it's the same kind of USB enclosure, with some references to underflow, which is what's triggering the error I get).

kernel patch to fix this bug is attached to the bug above: http://bugzilla.kernel.org/attachment.cgi?id=18207

Fixed in 2.6.27.4-46.rc3