Por que o 'ioerr_cnt' está subindo, sem mostrar nenhuma mensagem no 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

: (

Depois de um minuto mais tarde, sem fazer nada:

$ cat ioerr_cnt
0x391

: ((

De acordo com um artigo da IBM, ioerr_cnt significa "o número de comandos SCSI que foram concluídos com um erro".

Meu log atual do kernel ( dmesg ) não mostra nenhum erro de E / S, nenhum erro de SCSI ou ATA ou AHCI.

Por que a falha dos comandos SCSI, como o acima, não aparece no log do kernel? Normalmente, se você tiver um DVD problemático ou pendrive, você terá muito barulho sobre erros e novas tentativas, etc.

Posso ver os comandos SCSI com falha ou rastrear o código relevante de alguma forma?

Para ser claro, no caso de fazer alguma diferença, este é um dispositivo SATA (usando a tradução SCSI ATA como de costume para o Linux). Também é o meu disco rígido interno do laptop, por isso, se houvesse quaisquer erros de E / S "reais", gostaria de saber :). Motivo ulterior para olhar para este contador em primeiro lugar: Eu estou tentando depurar alguns erros de E / S bastante silenciosos que causam falha no resumo da suspensão .

Versão do kernel: 4.15.12-301.fc27.x86_64

Editar: blktrace

blktrace deve poder monitorar comandos SCSI e mostrar erros. Eu corri ao longo de um intervalo com 0x3A5 - 0x3A0 = 5 erros. Em seguida, executei blkparse com %e adicionado ao final da string de formato padrão para mostrar os códigos de erro:

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

No entanto, a pesquisa da saída por erros usando grep -vE "( 0)|( )$ não mostrou nenhum resultado.

Editar: 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 parece aumentar ao mesmo tempo que as mensagens acima.

SCSI ioctl () 0x2285 é SG_IO , ou seja, a submissão do espaço do usuário de um comando SCSI específico.

Estou lutando um pouco para descobrir qual processo faz isso. sudo lsof +D /dev/ parece não mostrar nenhum processo com um dispositivo SCSI atualmente aberto, mas não vejo nenhuma chamada open () relevante no momento dos erros ( cd /dev && sudo fatrace -c ).

Muitas vezes, o intervalo entre esses eventos (6 ioctls e 5 ioerr, como acima) é exatamente 10 minutos.

    

Answer 1

udisks polls drives a cada dez minutos, p. para dados SMART .

Eu esperaria que drives diferentes tivessem coisas diferentes que pudessem ser pesquisadas. Faz sentido que os udisks não consigam adivinhar com antecedência, exatamente quais comandos SCSI seriam bem-sucedidos ou falharão em um determinado dispositivo.

Portanto, ao executar os udisks, é de se esperar que ioerr_cnt aumente a cada dez minutos.

Eu não quero que veja erros no log do kernel, sempre que eu usei um programa para verificar dados SMART ou similares. (Embora eu não saiba exatamente que mecanismo o kernel usa, para decidir que essas falhas não são suficientemente interessantes). E eu espero que os udisks etc não precisem de uma série prolongada de tentativas ou reconfigurações (que é outra coisa que pode fazer com que as coisas apareçam nos logs), pois uma falha que ele pode dizer é causada por um recurso não suportado.

(Parece que fatrace não exibiu esse dispositivo sendo aberto pelos udisks porque ele não mostra nenhum dispositivo aberto. Consulte: Por que o 'fatrace' não detecta certos eventos abertos (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