Why is `ioerr_cnt` rising, without showing any messages in the log?

Question

$ cd /sys/devices/pci0000:00/0000:00:1f.2/ata2/host1/target1:0:0/1:0:0:0
$ ls -l driver subsystem
lrwxrwxrwx. 1 root root 0 Apr  5 10:48 driver -> ../../../../../../../bus/scsi/drivers/sd
lrwxrwxrwx. 1 root root 0 Apr  3 08:48 subsystem -> ../../../../../../../bus/scsi
$ cat ioerr_cnt 
0x38c

:(

After maybe a minute later, not really doing anything:

$ cat ioerr_cnt
0x391

:((

According to an IBM article, ioerr_cnt means "the number of SCSI commands that completed with an error".

My current kernel log (dmesg) shows no I/O error, no error from SCSI or ATA or AHCI.

Why might failing SCSI commands like the above not appear in the kernel log? Usually if you have a troublesome DVD, or USB stick, you get lots of nice noise about errors and retries etc.

Can I see the failing SCSI commands, or trace the relevant code somehow?

To be clear, in case it makes any difference this is a SATA device (using the SCSI ATA Translation as usual for Linux). Also it's my laptop internal hard drive, so if there were any "real" IO errors I would like to know :). Ulterior motive for looking at this counter in the first place: I am trying to debug some rather quiet IO errors that cause crashes on resume from suspend.

Kernel version: 4.15.12-301.fc27.x86_64

Edit: blktrace

blktrace is supposed to be able to monitor SCSI commands and show errors. I ran it over an interval with 0x3a5 - 0x3a0 = 5 errors. Then ran blkparse with %e added to the end of the default format string, to show error codes:

blkparse -f "%D %2c %8s %5T.%9t %5p %2a %3d %e\n"

However, searching the output for errors using grep -vE "( 0)|( )$ did not show any results.

Edit: scsi_logging_level

# scsi_logging_level -s --error=7 --ioctl=7  # from sg3-utils package
# dmesg -w
...
[112831.843993] sd 1:0:0:0: scsi_block_when_processing_errors: rtn: 1
[112831.844004] sd 1:0:0:0: [sda] sd_ioctl: disk=sda, cmd=0x2285
[112831.844007] sd 1:0:0:0: scsi_block_when_processing_errors: rtn: 1
[112831.844012] sd 1:0:0:0: [sda] sd_ioctl: disk=sda, cmd=0x2285
[112831.844015] sd 1:0:0:0: scsi_block_when_processing_errors: rtn: 1
[112831.900267] sd 1:0:0:0: scsi_block_when_processing_errors: rtn: 1
[112831.901394] sd 1:0:0:0: [sda] sd_ioctl: disk=sda, cmd=0x2285
[112831.901397] sd 1:0:0:0: scsi_block_when_processing_errors: rtn: 1
[112831.987030] sd 1:0:0:0: [sda] sd_ioctl: disk=sda, cmd=0x2285
[112831.987034] sd 1:0:0:0: scsi_block_when_processing_errors: rtn: 1
[112832.016745] sd 1:0:0:0: [sda] sd_ioctl: disk=sda, cmd=0x2285
[112832.016749] sd 1:0:0:0: scsi_block_when_processing_errors: rtn: 1
[112832.060156] sd 1:0:0:0: [sda] sd_ioctl: disk=sda, cmd=0x2285
[112832.060160] sd 1:0:0:0: scsi_block_when_processing_errors: rtn: 1
[112832.224840] sd 1:0:0:0: scsi_block_when_processing_errors: rtn: 1

ioerr_cnt seems to rise at the same time as the above messages.

SCSI ioctl() 0x2285 is SG_IO, i.e. userspace submission of a specific SCSI command.

I'm struggling a bit to work out what process does this. sudo lsof +D /dev/ doesn't seem to show any processes with a SCSI device currently open, but I don't see any relevant open() calls at the time of the errors either (cd /dev && sudo fatrace -c).

Often the interval between these events (6 ioctls and 5 ioerr, as above) is exactly 10 minutes.

Answer 1

udisks polls drives every ten minutes e.g. for SMART data.

I would expect different drives to have different things that can be polled. It makes sense that udisks might not manage to guess in advance, exactly what SCSI commands would succeed or fail on a given device.

So when running udisks, it is to be expected that ioerr_cnt rises every ten minutes.

I wouldn't want to see errors in the kernel log, whenever I used a program to check SMART data or similar. (Though I don't exactly what mechanism the kernel uses, to decide that these failures are not sufficiently interesting). And I expect udisks etc wouldn't want a prolonged series of retries or resets (which is something else that might cause things showing up in the logs), for a failure which it can tell is caused by an unsupported feature.

(It seems fatrace did not show this device being opened by udisks because it doesn't show any device opens. See: Why does `fatrace` not detect certain open events (udisks /dev/sda)?).

---

$ ps -ax|grep udisksd
  810 ?        Ssl    0:13 /usr/libexec/udisks2/udisksd
$ sudo strace -t -f -p 810
[pid   810] 14:11:09 clone(strace: Process 26543 attached
child_stack=0x7f8fc551ddf0, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0x7f8fc551e9d0, tls=0x7f8fc551e700, child_tidptr=0x7f8fc551e9d0) = 26543
[pid 26543] 14:11:09 set_robust_list(0x7f8fc551e9e0, 24 <unfinished ...>
[pid   810] 14:11:09 poll([{fd=4, events=POLLIN}, {fd=8, events=0}, {fd=9, events=0}, {fd=11, events=POLLIN}, {fd=13, events=POLLIN}], 5, 599968 <unfinished ...>
[pid 26543] 14:11:09 <... set_robust_list resumed> ) = 0
[pid 26543] 14:11:09 prctl(PR_SET_NAME, "pool") = 0
[pid 26543] 14:11:09 openat(AT_FDCWD, "/dev/sda", O_RDONLY|O_NONBLOCK) = 14
[pid 26543] 14:11:09 ioctl(14, SG_IO, {guard='Q', protocol=BSG_PROTOCOL_SCSI, subprotocol=BSG_SUB_PROTOCOL_SCSI_CMD, request_len=16, request="\x85\x06\x20\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\xe5\x00", request_tag=0, request_attr=0, request_priority=0, request_extra=0, max_response_len=32, dout_iovec_count=0, dout_xfer_len=0, din_iovec_count=0, din_xfer_len=0, dout_xferp=NULL, timeout=5000, flags=0, usr_ptr=0, response_len=0, response="", din_xferp=NULL, driver_status=0, transport_status=0, device_status=0, retry_delay=0, info=0, duration=0, response_len=0, din_resid=0, dout_resid=0, generated_tag=0}) = -1 EINVAL (Invalid argument)
[pid 26543] 14:11:09 ioctl(14, SG_IO, {interface_id='S', dxfer_direction=SG_DXFER_NONE, cmd_len=16, cmdp="\x85\x06\x20\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\xe5\x00", mx_sb_len=32, iovec_count=0, dxfer_len=0, timeout=5000, flags=0, status=0x2, masked_status=0x1, msg_status=0, sb_len_wr=22, sbp="\x72\x01\x00\x1d\x00\x00\x00\x0e\x09\x0c\x00\x00\x00\xff\x00\x00\x00\x00\x00\x00\x00\x50", host_status=0, driver_status=0x8, resid=0, duration=11, info=SG_INFO_CHECK}) = 0
[pid 26543] 14:11:09 close(14)          = 0
[pid 26543] 14:11:09 openat(AT_FDCWD, "/dev/sda", O_RDONLY|O_NOCTTY|O_NONBLOCK|O_CLOEXEC) = 14
[pid 26543] 14:11:09 fstat(14, {st_mode=S_IFBLK|0660, st_rdev=makedev(8, 0), ...}) = 0
[pid 26543] 14:11:09 ioctl(14, BLKGETSIZE64, [500107862016]) = 0
[pid 26543] 14:11:09 readlinkat(AT_FDCWD, "/sys/dev/block/8:0", "../../devices/pci0000:00/0000:00"..., 99) = 78
[pid 26543] 14:11:09 openat(AT_FDCWD, "/", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = 16
[pid 26543] 14:11:09 openat(16, "sys", O_RDONLY|O_NOFOLLOW|O_CLOEXEC|O_PATH) = 17
[pid 26543] 14:11:09 fstat(17, {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
[pid 26543] 14:11:09 close(16)          = 0
...
[pid 26543] 14:11:09 ioctl(14, SG_IO, {interface_id='S', dxfer_direction=SG_DXFER_FROM_DEV, cmd_len=16, cmdp="\x85\x08\x2e\x00\x00\x00\x01\x00\x00\x00\x00\x00\x00\x00\xec\x00", mx_sb_len=32, iovec_count=0, dxfer_len=512, timeout=2000, flags=0, dxferp="\x7a\x42\xff\x3f\x37\xc8\x10\x00\x00\x00\x00\x00\x3f\x00\x00\x00\x00\x00\x00\x00\x20\x20\x20\x20\x20\x20\x20\x20\x58\x57\x31\x37"..., status=0x2, masked_status=0x1, msg_status=0, sb_len_wr=22, sbp="\x72\x01\x00\x1d\x00\x00\x00\x0e\x09\x0c\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x50", host_status=0, driver_status=0x8, resid=0, duration=7, info=SG_INFO_CHECK}) = 0
[pid 26543] 14:11:09 ioctl(14, SG_IO, {interface_id='S', dxfer_direction=SG_DXFER_FROM_DEV, cmd_len=16, cmdp="\x85\x08\x2e\x00\xd1\x00\x01\x00\x00\x00\x4f\x00\xc2\x00\xb0\x00", mx_sb_len=32, iovec_count=0, dxfer_len=512, timeout=2000, flags=0, dxferp="\x10\x00\x01\x33\xc8\xc8\x00\x00\x00\x00\x00\x00\x00\x00\x03\x15\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x04\x00\x00\x00\x00\x00"..., status=0x2, masked_status=0x1, msg_status=0, sb_len_wr=22, sbp="\x72\x01\x00\x1d\x00\x00\x00\x0e\x09\x0c\x00\x00\x00\x00\x00\x00\x00\x4f\x00\xc2\x00\x50", host_status=0, driver_status=0x8, resid=0, duration=30, info=SG_INFO_CHECK}) = 0
[pid 26543] 14:11:09 ioctl(14, SG_IO, {interface_id='S', dxfer_direction=SG_DXFER_FROM_DEV, cmd_len=16, cmdp="\x85\x08\x2e\x00\xd0\x00\x01\x00\x00\x00\x4f\x00\xc2\x00\xb0\x00", mx_sb_len=32, iovec_count=0, dxfer_len=512, timeout=2000, flags=0, dxferp="\x10\x00\x01\x2f\x00\xc8\xc8\x00\x00\x00\x00\x00\x00\x00\x03\x27\x00\x8e\x8d\x6c\x07\x00\x00\x00\x00\x00\x04\x32\x00\x60\x60\x46"..., status=0x2, masked_status=0x1, msg_status=0, sb_len_wr=22, sbp="\x72\x01\x00\x1d\x00\x00\x00\x0e\x09\x0c\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x50", host_status=0, driver_status=0x8, resid=0, duration=18, info=SG_INFO_CHECK}) = 0
[pid 26543] 14:11:09 ioctl(14, SG_IO, {interface_id='S', dxfer_direction=SG_DXFER_NONE, cmd_len=16, cmdp="\x85\x06\x20\x00\xda\x00\x00\x00\x00\x00\x4f\x00\xc2\x00\xb0\x00", mx_sb_len=32, iovec_count=0, dxfer_len=0, timeout=2000, flags=0, status=0x2, masked_status=0x1, msg_status=0, sb_len_wr=22, sbp="\x72\x01\x00\x1d\x00\x00\x00\x0e\x09\x0c\x00\x00\x00\x00\x00\x00\x00\x4f\x00\xc2\x00\x50", host_status=0, driver_status=0x8, resid=0, duration=37, info=SG_INFO_CHECK}) = 0