[RFC,v3,0/8] Add persistent durable identifier to storage log messages

Message

Tony Asleson June 23, 2020, 7:17 p.m. UTC

Today users have no easy way to correlate kernel log messages for storage
devices across reboots, device dynamic add/remove, or when the device is
physically or logically moved from from system to system.  This is due
to the existing log IDs which identify how the device is attached and not
a unique ID of what is attached.  Additionally, even when the attachment
hasn't changed, it's not always obvious which messages belong to the
device as the different areas in the storage stack use different
identifiers, eg. (sda, sata1.00, sd 0:0:0:0).

This change addresses this by adding a unique ID to each log
message.  It couples the existing structured key/value logging capability
and VPD 0x83 device identification.


An example of logs filtered for a specific device utilizing this patch
series.

$ journalctl -b  _KERNEL_DURABLE_NAME="`cat /sys/block/sdb/device/wwid`"
| cut -c 25- | fmt -t
9-08-22 13:21:35 CDT, end at Wed 2020-05-13 15:40:26 CDT. --
l: scsi 1:0:0:0: Attached scsi generic sg1 type 0
l: sd 1:0:0:0: [sdb] 209715200 512-byte logical blocks: (107 GB/100 GiB)
l: sd 1:0:0:0: [sdb] Write Protect is off
l: sd 1:0:0:0: [sdb] Mode Sense: 00 3a 00 00
l: sd 1:0:0:0: [sdb] Write cache: enabled, read cache: enabled, doesn't
   support DPO or FUA
l: sd 1:0:0:0: [sdb] Attached SCSI disk
l: sd 1:0:0:0: ata2.00: exception Emask 0x0 SAct 0x800000 SErr 0x800000
   action 0x6 frozen
l: sd 1:0:0:0: ata2.00: failed command: READ FPDMA QUEUED
l: sd 1:0:0:0: ata2.00: cmd 60/20:b8:10:27:00/00:00:00:00:00/40 tag 23
            ncq dma 16384 in res 40/00:00:00:4f:c2/00:00:00:00:00/00
            Emask 0x4 (timeout)
l: sd 1:0:0:0: ata2.00: status: { DRDY }
l: sd 1:0:0:0: ata2.00: configured for UDMA/100
l: sd 1:0:0:0: [sdb] tag#23 FAILED Result: hostbyte=DID_OK
            driverbyte=DRIVER_SENSE cmd_age=30s
l: sd 1:0:0:0: [sdb] tag#23 Sense Key : Illegal Request [current]
l: sd 1:0:0:0: [sdb] tag#23 Add. Sense: Unaligned write command
l: sd 1:0:0:0: [sdb] tag#23 CDB: Read(10) 28 00 00 00 27 10 00 00 20 00
l: block sdb: blk_update_request: I/O error, dev sdb, sector 10000 op
            0x0:(READ) flags 0x80700 phys_seg 4 prio class 0
l: sd 1:0:0:0: ata2.00: exception Emask 0x0 SAct 0x2 SErr 0x2 action
            0x6 frozen
l: sd 1:0:0:0: ata2.00: failed command: READ FPDMA QUEUED
l: sd 1:0:0:0: ata2.00: cmd 60/08:08:10:27:00/00:00:00:00:00/40 tag 1 ncq
            dma 4096 in res 40/00:ff:00:00:00/00:00:00:00:00/00 Emask 0x4
            (timeout)
l: sd 1:0:0:0: ata2.00: status: { DRDY }
l: sd 1:0:0:0: ata2.00: configured for UDMA/100
l: sd 1:0:0:0: ata2.00: exception Emask 0x0 SAct 0x800000 SErr 0x800000
            action 0x6 frozen
l: sd 1:0:0:0: ata2.00: failed command: READ FPDMA QUEUED
l: sd 1:0:0:0: ata2.00: cmd 60/08:b8:10:27:00/00:00:00:00:00/40 tag 23 ncq
            dma 4096 in res 40/00:00:00:4f:c2/00:00:00:00:00/00 Emask 0x4
            (timeout)
l: sd 1:0:0:0: ata2.00: status: { DRDY }
l: sd 1:0:0:0: ata2.00: configured for UDMA/100
l: sd 1:0:0:0: ata2.00: NCQ disabled due to excessive errors
l: sd 1:0:0:0: ata2.00: exception Emask 0x0 SAct 0x4000 SErr 0x4000
            action 0x6 frozen
l: sd 1:0:0:0: ata2.00: failed command: READ FPDMA QUEUED
l: sd 1:0:0:0: ata2.00: cmd 60/08:70:10:27:00/00:00:00:00:00/40 tag 14 ncq
            dma 4096 in res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4
            (timeout)
l: sd 1:0:0:0: ata2.00: status: { DRDY }
l: sd 1:0:0:0: ata2.00: configured for UDMA/100
l: sd 1:0:0:0: ata2.00: device reported invalid CHS sector 0

This change is incomplete.  With the plethora of different logging
techniques utilized in the kernel it will take some coordinated effort
and additional changes.  I tried a few different approaches, to cover
as much as I could without resorting to changing every print statement
in all the storage layers, but maybe there is a better,
more elegant approach?

I believe having this functionality is very useful and important for
system configurations of all sizes.  I mentioned this change briefly in:
https://lore.kernel.org/lkml/[e-mail]/

Questions
1. Where is the best place to put the durable_name callback function?
2. What is best "KEY" value?
3. Should we re-work the message contents themselves to remove any redundant
   information that is included when using dev_printk? ref. 
   https://lore.kernel.org/linux-scsi/[e-mail]/#t


v2:
- Incorporated changes suggested by James Bottomley
- Removed string function which removed leading/trailing/duplicate adjacent
  spaces from generated id, value matches /sys/block/<device>/device/wwid
- Remove xfs patch, limiting changes to lower block layers
- Moved callback from struct device_type to struct device.  Struct device_type
  is typically static const and with a number of different areas using shared
  implementation of genhd unable to modify for each of the different areas.

v3:
- Increase the size of the buffers for NVMe id generation and
  dev_vprintk_emit

Tony Asleson (8):
  struct device: Add function callback durable_name
  create_syslog_header: Add durable name
  print_req_error: Use dev_printk
  buffer_io_error: Use dev_printk
  ata_dev_printk: Use dev_printk
  scsi: Add durable_name for dev_printk
  nvme: Add durable name for dev_printk
  dev_vprintk_emit: Increase hdr size

 block/blk-core.c           |  5 ++++-
 drivers/ata/libata-core.c  | 10 +++++++---
 drivers/base/core.c        | 31 ++++++++++++++++++++++++++++++-
 drivers/nvme/host/core.c   | 18 ++++++++++++++++++
 drivers/scsi/scsi_lib.c    | 14 ++++++++++++++
 drivers/scsi/scsi_sysfs.c  | 23 +++++++++++++++++++++++
 drivers/scsi/sd.c          |  2 ++
 fs/buffer.c                | 10 ++++++++--
 include/linux/device.h     |  4 ++++
 include/scsi/scsi_device.h |  3 +++
 10 files changed, 113 insertions(+), 7 deletions(-)


base-commit: 3d77e6a8804abcc0504c904bd6e5cdf3a5cf8162