Linux-Block Archive on lore.kernel.org
 help / color / Atom feed
* [RFC PATCH v2 0/7] Add persistent durable identifier to storage log messages
@ 2020-05-13 21:36 Tony Asleson
  2020-05-13 21:36 ` [RFC PATCH v2 1/7] struct device: Add function callback durable_name Tony Asleson
                   ` (6 more replies)
  0 siblings, 7 replies; 14+ messages in thread
From: Tony Asleson @ 2020-05-13 21:36 UTC (permalink / raw)
  To: linux-scsi, linux-block

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/30f29fe6-8445-0016-8cdc-3ef99d43fbf5@redhat.com/

Questions
1. Where is the best place to put the durable_name callback function?
2. What is best "KEY" value?


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.

Tony Asleson (7):
  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

 block/blk-core.c           |  5 ++++-
 drivers/ata/libata-core.c  | 10 +++++++---
 drivers/base/core.c        | 29 +++++++++++++++++++++++++++++
 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, 112 insertions(+), 6 deletions(-)


base-commit: 7111951b8d4973bda27ff663f2cf18b663d15b48
-- 
2.25.4


^ permalink raw reply	[flat|nested] 14+ messages in thread

* [RFC PATCH v2 1/7] struct device: Add function callback durable_name
  2020-05-13 21:36 [RFC PATCH v2 0/7] Add persistent durable identifier to storage log messages Tony Asleson
@ 2020-05-13 21:36 ` Tony Asleson
  2020-05-13 21:36 ` [RFC PATCH v2 2/7] create_syslog_header: Add durable name Tony Asleson
                   ` (5 subsequent siblings)
  6 siblings, 0 replies; 14+ messages in thread
From: Tony Asleson @ 2020-05-13 21:36 UTC (permalink / raw)
  To: linux-scsi, linux-block

Function callback and function to be used to write a persistent
durable name to the supplied character buffer.  This will be used to add
structured key-value data to log messages for hardware related errors
which allows end users to correlate message and specific hardware.

Signed-off-by: Tony Asleson <tasleson@redhat.com>
---
 drivers/base/core.c    | 24 ++++++++++++++++++++++++
 include/linux/device.h |  4 ++++
 2 files changed, 28 insertions(+)

diff --git a/drivers/base/core.c b/drivers/base/core.c
index dbb0f9130f42..86ea3acb1e1f 100644
--- a/drivers/base/core.c
+++ b/drivers/base/core.c
@@ -2281,6 +2281,30 @@ int dev_set_name(struct device *dev, const char *fmt, ...)
 }
 EXPORT_SYMBOL_GPL(dev_set_name);
 
+/**
+ * dev_durable_name - Write "DURABLE_NAME"=<durable name> in buffer
+ * @dev: device
+ * @buffer: character buffer to write results
+ * @len: length of buffer
+ * @return: Number of bytes written to buffer
+ */
+int dev_durable_name(const struct device *dev, char *buffer, size_t len)
+{
+	int tmp, dlen;
+
+	if (dev && dev->durable_name) {
+		tmp = snprintf(buffer, len, "DURABLE_NAME=");
+		if (tmp < len) {
+			dlen = dev->durable_name(dev, buffer + tmp,
+							len - tmp);
+			if (dlen > 0 && ((dlen + tmp) < len))
+				return dlen + tmp;
+		}
+	}
+	return 0;
+}
+EXPORT_SYMBOL_GPL(dev_durable_name);
+
 /**
  * device_to_dev_kobj - select a /sys/dev/ directory for the device
  * @dev: device
diff --git a/include/linux/device.h b/include/linux/device.h
index fa04dfd22bbc..a9e5abbd2269 100644
--- a/include/linux/device.h
+++ b/include/linux/device.h
@@ -616,6 +616,8 @@ struct device {
 	struct iommu_fwspec	*iommu_fwspec;
 	struct iommu_param	*iommu_param;
 
+	int (*durable_name)(const struct device *dev, char *buff, size_t len);
+
 	bool			offline_disabled:1;
 	bool			offline:1;
 	bool			of_node_reused:1;
@@ -657,6 +659,8 @@ static inline const char *dev_name(const struct device *dev)
 extern __printf(2, 3)
 int dev_set_name(struct device *dev, const char *name, ...);
 
+int dev_durable_name(const struct device *d, char *buffer, size_t len);
+
 #ifdef CONFIG_NUMA
 static inline int dev_to_node(struct device *dev)
 {
-- 
2.25.4


^ permalink raw reply	[flat|nested] 14+ messages in thread

* [RFC PATCH v2 2/7] create_syslog_header: Add durable name
  2020-05-13 21:36 [RFC PATCH v2 0/7] Add persistent durable identifier to storage log messages Tony Asleson
  2020-05-13 21:36 ` [RFC PATCH v2 1/7] struct device: Add function callback durable_name Tony Asleson
@ 2020-05-13 21:36 ` Tony Asleson
  2020-05-13 21:36 ` [RFC PATCH v2 3/7] print_req_error: Use dev_printk Tony Asleson
                   ` (4 subsequent siblings)
  6 siblings, 0 replies; 14+ messages in thread
From: Tony Asleson @ 2020-05-13 21:36 UTC (permalink / raw)
  To: linux-scsi, linux-block

This gets us a persistent durable name for code that logs messages in the
block layer that have the appropriate callbacks setup for durable name.

Signed-off-by: Tony Asleson <tasleson@redhat.com>
---
 drivers/base/core.c | 5 +++++
 1 file changed, 5 insertions(+)

diff --git a/drivers/base/core.c b/drivers/base/core.c
index 86ea3acb1e1f..8c89b711d91d 100644
--- a/drivers/base/core.c
+++ b/drivers/base/core.c
@@ -3577,6 +3577,7 @@ create_syslog_header(const struct device *dev, char *hdr, size_t hdrlen)
 {
 	const char *subsys;
 	size_t pos = 0;
+	int dlen;
 
 	if (dev->class)
 		subsys = dev->class->name;
@@ -3619,6 +3620,10 @@ create_syslog_header(const struct device *dev, char *hdr, size_t hdrlen)
 				"DEVICE=+%s:%s", subsys, dev_name(dev));
 	}
 
+	dlen = dev_durable_name(dev, hdr + (pos + 1), hdrlen - (pos + 1));
+	if (dlen)
+		pos += dlen + 1;
+
 	if (pos >= hdrlen)
 		goto overflow;
 
-- 
2.25.4


^ permalink raw reply	[flat|nested] 14+ messages in thread

* [RFC PATCH v2 3/7] print_req_error: Use dev_printk
  2020-05-13 21:36 [RFC PATCH v2 0/7] Add persistent durable identifier to storage log messages Tony Asleson
  2020-05-13 21:36 ` [RFC PATCH v2 1/7] struct device: Add function callback durable_name Tony Asleson
  2020-05-13 21:36 ` [RFC PATCH v2 2/7] create_syslog_header: Add durable name Tony Asleson
@ 2020-05-13 21:36 ` Tony Asleson
  2020-05-13 21:36 ` [RFC PATCH v2 4/7] buffer_io_error: " Tony Asleson
                   ` (3 subsequent siblings)
  6 siblings, 0 replies; 14+ messages in thread
From: Tony Asleson @ 2020-05-13 21:36 UTC (permalink / raw)
  To: linux-scsi, linux-block

Signed-off-by: Tony Asleson <tasleson@redhat.com>
---
 block/blk-core.c | 5 ++++-
 1 file changed, 4 insertions(+), 1 deletion(-)

diff --git a/block/blk-core.c b/block/blk-core.c
index 60dc9552ef8d..44bf92047031 100644
--- a/block/blk-core.c
+++ b/block/blk-core.c
@@ -213,12 +213,15 @@ EXPORT_SYMBOL_GPL(blk_status_to_errno);
 static void print_req_error(struct request *req, blk_status_t status,
 		const char *caller)
 {
+	struct device *dev;
 	int idx = (__force int)status;
 
 	if (WARN_ON_ONCE(idx >= ARRAY_SIZE(blk_errors)))
 		return;
 
-	printk_ratelimited(KERN_ERR
+	dev = (req->rq_disk) ? disk_to_dev(req->rq_disk) : NULL;
+
+	dev_err_ratelimited(dev,
 		"%s: %s error, dev %s, sector %llu op 0x%x:(%s) flags 0x%x "
 		"phys_seg %u prio class %u\n",
 		caller, blk_errors[idx].name,
-- 
2.25.4


^ permalink raw reply	[flat|nested] 14+ messages in thread

* [RFC PATCH v2 4/7] buffer_io_error: Use dev_printk
  2020-05-13 21:36 [RFC PATCH v2 0/7] Add persistent durable identifier to storage log messages Tony Asleson
                   ` (2 preceding siblings ...)
  2020-05-13 21:36 ` [RFC PATCH v2 3/7] print_req_error: Use dev_printk Tony Asleson
@ 2020-05-13 21:36 ` Tony Asleson
  2020-05-13 21:36 ` [RFC PATCH v2 5/7] ata_dev_printk: " Tony Asleson
                   ` (2 subsequent siblings)
  6 siblings, 0 replies; 14+ messages in thread
From: Tony Asleson @ 2020-05-13 21:36 UTC (permalink / raw)
  To: linux-scsi, linux-block

Signed-off-by: Tony Asleson <tasleson@redhat.com>
---
 fs/buffer.c | 10 ++++++++--
 1 file changed, 8 insertions(+), 2 deletions(-)

diff --git a/fs/buffer.c b/fs/buffer.c
index b8d28370cfd7..e144f5bccd2f 100644
--- a/fs/buffer.c
+++ b/fs/buffer.c
@@ -133,10 +133,16 @@ __clear_page_buffers(struct page *page)
 
 static void buffer_io_error(struct buffer_head *bh, char *msg)
 {
-	if (!test_bit(BH_Quiet, &bh->b_state))
-		printk_ratelimited(KERN_ERR
+	if (!test_bit(BH_Quiet, &bh->b_state)) {
+		struct device *gendev;
+
+		gendev = (bh->b_bdev->bd_disk) ?
+			disk_to_dev(bh->b_bdev->bd_disk) : NULL;
+
+		dev_err_ratelimited(gendev,
 			"Buffer I/O error on dev %pg, logical block %llu%s\n",
 			bh->b_bdev, (unsigned long long)bh->b_blocknr, msg);
+	}
 }
 
 /*
-- 
2.25.4


^ permalink raw reply	[flat|nested] 14+ messages in thread

* [RFC PATCH v2 5/7] ata_dev_printk: Use dev_printk
  2020-05-13 21:36 [RFC PATCH v2 0/7] Add persistent durable identifier to storage log messages Tony Asleson
                   ` (3 preceding siblings ...)
  2020-05-13 21:36 ` [RFC PATCH v2 4/7] buffer_io_error: " Tony Asleson
@ 2020-05-13 21:36 ` Tony Asleson
  2020-05-14  5:53   ` Hannes Reinecke
  2020-05-13 21:36 ` [RFC PATCH v2 6/7] scsi: Add durable_name for dev_printk Tony Asleson
  2020-05-13 21:36 ` [RFC PATCH v2 7/7] nvme: Add durable name " Tony Asleson
  6 siblings, 1 reply; 14+ messages in thread
From: Tony Asleson @ 2020-05-13 21:36 UTC (permalink / raw)
  To: linux-scsi, linux-block

Utilize the dev_printk function which will add structured data
to the log message.

Signed-off-by: Tony Asleson <tasleson@redhat.com>
---
 drivers/ata/libata-core.c | 10 +++++++---
 1 file changed, 7 insertions(+), 3 deletions(-)

diff --git a/drivers/ata/libata-core.c b/drivers/ata/libata-core.c
index 42c8728f6117..16978d615a17 100644
--- a/drivers/ata/libata-core.c
+++ b/drivers/ata/libata-core.c
@@ -7301,6 +7301,7 @@ EXPORT_SYMBOL(ata_link_printk);
 void ata_dev_printk(const struct ata_device *dev, const char *level,
 		    const char *fmt, ...)
 {
+	const struct device *gendev;
 	struct va_format vaf;
 	va_list args;
 
@@ -7309,9 +7310,12 @@ void ata_dev_printk(const struct ata_device *dev, const char *level,
 	vaf.fmt = fmt;
 	vaf.va = &args;
 
-	printk("%sata%u.%02u: %pV",
-	       level, dev->link->ap->print_id, dev->link->pmp + dev->devno,
-	       &vaf);
+	gendev = (dev->sdev) ? &dev->sdev->sdev_gendev : &dev->tdev;
+
+	dev_printk(level, gendev, "ata%u.%02u: %pV",
+			dev->link->ap->print_id,
+			dev->link->pmp + dev->devno,
+			&vaf);
 
 	va_end(args);
 }
-- 
2.25.4


^ permalink raw reply	[flat|nested] 14+ messages in thread

* [RFC PATCH v2 6/7] scsi: Add durable_name for dev_printk
  2020-05-13 21:36 [RFC PATCH v2 0/7] Add persistent durable identifier to storage log messages Tony Asleson
                   ` (4 preceding siblings ...)
  2020-05-13 21:36 ` [RFC PATCH v2 5/7] ata_dev_printk: " Tony Asleson
@ 2020-05-13 21:36 ` Tony Asleson
  2020-05-13 21:36 ` [RFC PATCH v2 7/7] nvme: Add durable name " Tony Asleson
  6 siblings, 0 replies; 14+ messages in thread
From: Tony Asleson @ 2020-05-13 21:36 UTC (permalink / raw)
  To: linux-scsi, linux-block

Add the needed functions to fill out the durable_name function
call back for scsi based storage devices.  This allows calls
into dev_printk for scsi devices to have a persistent id
associated with them.

Signed-off-by: Tony Asleson <tasleson@redhat.com>
---
 drivers/scsi/scsi_lib.c    | 14 ++++++++++++++
 drivers/scsi/scsi_sysfs.c  | 23 +++++++++++++++++++++++
 drivers/scsi/sd.c          |  2 ++
 include/scsi/scsi_device.h |  3 +++
 4 files changed, 42 insertions(+)

diff --git a/drivers/scsi/scsi_lib.c b/drivers/scsi/scsi_lib.c
index 610ee41fa54c..482e41ec23c2 100644
--- a/drivers/scsi/scsi_lib.c
+++ b/drivers/scsi/scsi_lib.c
@@ -3121,3 +3121,17 @@ int scsi_vpd_tpg_id(struct scsi_device *sdev, int *rel_id)
 	return group_id;
 }
 EXPORT_SYMBOL(scsi_vpd_tpg_id);
+
+int scsi_durable_name(struct scsi_device *sdev, char *buf, size_t len)
+{
+	int vpd_len = 0;
+
+	vpd_len = scsi_vpd_lun_id(sdev, buf, len);
+	if (vpd_len > 0 && vpd_len < len)
+		vpd_len++;
+	else
+		vpd_len = 0;
+
+	return vpd_len;
+}
+EXPORT_SYMBOL(scsi_durable_name);
diff --git a/drivers/scsi/scsi_sysfs.c b/drivers/scsi/scsi_sysfs.c
index 677b5c5403d2..f09f5c94ebbd 100644
--- a/drivers/scsi/scsi_sysfs.c
+++ b/drivers/scsi/scsi_sysfs.c
@@ -1582,6 +1582,28 @@ static struct device_type scsi_dev_type = {
 	.groups =	scsi_sdev_attr_groups,
 };
 
+
+int dev_to_scsi_durable_name(const struct device *dev, char *buf, size_t len)
+{
+	struct scsi_device *sd_dev = NULL;
+
+	// When we go through dev_printk in the scsi layer, dev is embedded
+	// in a struct scsi_device.  When we go through the block layer,
+	// dev is embedded in struct genhd, thus we need different paths to
+	// retrieve the struct scsi_device to call scsi_durable_name.
+	if (dev->type == &scsi_dev_type) {
+		sd_dev = to_scsi_device(dev);
+	} else if (dev->parent && dev->parent->type == &scsi_dev_type) {
+		sd_dev = to_scsi_device(dev->parent);
+	} else {
+		// We have a pointer to something else, bail
+		return 0;
+	}
+
+	return scsi_durable_name(sd_dev, buf, len);
+}
+EXPORT_SYMBOL(dev_to_scsi_durable_name);
+
 void scsi_sysfs_device_initialize(struct scsi_device *sdev)
 {
 	unsigned long flags;
@@ -1591,6 +1613,7 @@ void scsi_sysfs_device_initialize(struct scsi_device *sdev)
 	device_initialize(&sdev->sdev_gendev);
 	sdev->sdev_gendev.bus = &scsi_bus_type;
 	sdev->sdev_gendev.type = &scsi_dev_type;
+	sdev->sdev_gendev.durable_name = dev_to_scsi_durable_name;
 	dev_set_name(&sdev->sdev_gendev, "%d:%d:%d:%llu",
 		     sdev->host->host_no, sdev->channel, sdev->id, sdev->lun);
 
diff --git a/drivers/scsi/sd.c b/drivers/scsi/sd.c
index 2710a0e5ae6d..774f1a8910a2 100644
--- a/drivers/scsi/sd.c
+++ b/drivers/scsi/sd.c
@@ -3359,6 +3359,8 @@ static int sd_probe(struct device *dev)
 	gd->private_data = &sdkp->driver;
 	gd->queue = sdkp->device->request_queue;
 
+	disk_to_dev(gd)->durable_name = dev_to_scsi_durable_name;
+
 	/* defaults, until the device tells us otherwise */
 	sdp->sector_size = 512;
 	sdkp->capacity = 0;
diff --git a/include/scsi/scsi_device.h b/include/scsi/scsi_device.h
index f8312a3e5b42..496774ff79fc 100644
--- a/include/scsi/scsi_device.h
+++ b/include/scsi/scsi_device.h
@@ -459,6 +459,9 @@ extern void sdev_disable_disk_events(struct scsi_device *sdev);
 extern void sdev_enable_disk_events(struct scsi_device *sdev);
 extern int scsi_vpd_lun_id(struct scsi_device *, char *, size_t);
 extern int scsi_vpd_tpg_id(struct scsi_device *, int *);
+extern int dev_to_scsi_durable_name(const struct device *dev, char *buf,
+					size_t len);
+extern int scsi_durable_name(struct scsi_device *sdev, char *buf, size_t len);
 
 #ifdef CONFIG_PM
 extern int scsi_autopm_get_device(struct scsi_device *);
-- 
2.25.4


^ permalink raw reply	[flat|nested] 14+ messages in thread

* [RFC PATCH v2 7/7] nvme: Add durable name for dev_printk
  2020-05-13 21:36 [RFC PATCH v2 0/7] Add persistent durable identifier to storage log messages Tony Asleson
                   ` (5 preceding siblings ...)
  2020-05-13 21:36 ` [RFC PATCH v2 6/7] scsi: Add durable_name for dev_printk Tony Asleson
@ 2020-05-13 21:36 ` Tony Asleson
  2020-05-13 23:04   ` Keith Busch
  6 siblings, 1 reply; 14+ messages in thread
From: Tony Asleson @ 2020-05-13 21:36 UTC (permalink / raw)
  To: linux-scsi, linux-block

Signed-off-by: Tony Asleson <tasleson@redhat.com>
---
 drivers/nvme/host/core.c | 18 ++++++++++++++++++
 1 file changed, 18 insertions(+)

diff --git a/drivers/nvme/host/core.c b/drivers/nvme/host/core.c
index a4d8c90ee7cc..7479c7e82200 100644
--- a/drivers/nvme/host/core.c
+++ b/drivers/nvme/host/core.c
@@ -2614,6 +2614,22 @@ static bool nvme_validate_cntlid(struct nvme_subsystem *subsys,
 	return true;
 }
 
+static ssize_t wwid_show(struct device *dev, struct device_attribute *attr,
+			char *buf);
+
+static int dev_to_nvme_durable_name(const struct device *dev, char *buf, size_t len)
+{
+	char serial[128];
+	ssize_t serial_len = wwid_show((struct device *)dev, NULL, serial);
+
+	if (serial_len > 0 && serial_len < len) {
+		serial_len -= 1;  // Remove the '\n' from the string
+		strncpy(buf, serial, serial_len);
+		return serial_len;
+	}
+	return 0;
+}
+
 static int nvme_init_subsystem(struct nvme_ctrl *ctrl, struct nvme_id_ctrl *id)
 {
 	struct nvme_subsystem *subsys, *found;
@@ -3541,6 +3557,8 @@ static int nvme_alloc_ns(struct nvme_ctrl *ctrl, unsigned nsid)
 	disk->queue = ns->queue;
 	disk->flags = flags;
 	memcpy(disk->disk_name, disk_name, DISK_NAME_LEN);
+	disk_to_dev(disk)->durable_name = dev_to_nvme_durable_name;
+
 	ns->disk = disk;
 
 	__nvme_revalidate_disk(disk, id);
-- 
2.25.4


^ permalink raw reply	[flat|nested] 14+ messages in thread

* Re: [RFC PATCH v2 7/7] nvme: Add durable name for dev_printk
  2020-05-13 21:36 ` [RFC PATCH v2 7/7] nvme: Add durable name " Tony Asleson
@ 2020-05-13 23:04   ` Keith Busch
  2020-05-14 17:13     ` Tony Asleson
  0 siblings, 1 reply; 14+ messages in thread
From: Keith Busch @ 2020-05-13 23:04 UTC (permalink / raw)
  To: Tony Asleson; +Cc: linux-scsi, linux-block

On Wed, May 13, 2020 at 04:36:21PM -0500, Tony Asleson wrote:
> +static int dev_to_nvme_durable_name(const struct device *dev, char *buf, size_t len)
> +{
> +	char serial[128];
> +	ssize_t serial_len = wwid_show((struct device *)dev, NULL, serial);

wwid_show() can generate a serial larger than 128 bytes.

> +
> +	if (serial_len > 0 && serial_len < len) {
> +		serial_len -= 1;  // Remove the '\n' from the string

Comments in this driver should use the /* */ style.

> +		strncpy(buf, serial, serial_len);
> +		return serial_len;
> +	}
> +	return 0;
> +}

^ permalink raw reply	[flat|nested] 14+ messages in thread

* Re: [RFC PATCH v2 5/7] ata_dev_printk: Use dev_printk
  2020-05-13 21:36 ` [RFC PATCH v2 5/7] ata_dev_printk: " Tony Asleson
@ 2020-05-14  5:53   ` Hannes Reinecke
  2020-05-14 18:03     ` Tony Asleson
  0 siblings, 1 reply; 14+ messages in thread
From: Hannes Reinecke @ 2020-05-14  5:53 UTC (permalink / raw)
  To: Tony Asleson, linux-scsi, linux-block

On 5/13/20 11:36 PM, Tony Asleson wrote:
> Utilize the dev_printk function which will add structured data
> to the log message.
> 
> Signed-off-by: Tony Asleson <tasleson@redhat.com>
> ---
>   drivers/ata/libata-core.c | 10 +++++++---
>   1 file changed, 7 insertions(+), 3 deletions(-)
> 
> diff --git a/drivers/ata/libata-core.c b/drivers/ata/libata-core.c
> index 42c8728f6117..16978d615a17 100644
> --- a/drivers/ata/libata-core.c
> +++ b/drivers/ata/libata-core.c
> @@ -7301,6 +7301,7 @@ EXPORT_SYMBOL(ata_link_printk);
>   void ata_dev_printk(const struct ata_device *dev, const char *level,
>   		    const char *fmt, ...)
>   {
> +	const struct device *gendev;
>   	struct va_format vaf;
>   	va_list args;
>   
> @@ -7309,9 +7310,12 @@ void ata_dev_printk(const struct ata_device *dev, const char *level,
>   	vaf.fmt = fmt;
>   	vaf.va = &args;
>   
> -	printk("%sata%u.%02u: %pV",
> -	       level, dev->link->ap->print_id, dev->link->pmp + dev->devno,
> -	       &vaf);
> +	gendev = (dev->sdev) ? &dev->sdev->sdev_gendev : &dev->tdev;
> +
> +	dev_printk(level, gendev, "ata%u.%02u: %pV",
> +			dev->link->ap->print_id,
> +			dev->link->pmp + dev->devno,
> +			&vaf);
>   
>   	va_end(args);
>   }
> 
That is wrong.
dev_printk() will already prefix the logging message with the device 
name, so we'll end up having the name printed twice.

Cheers,

Hannes
-- 
Dr. Hannes Reinecke            Teamlead Storage & Networking
hare@suse.de                               +49 911 74053 688
SUSE Software Solutions GmbH, Maxfeldstr. 5, 90409 Nürnberg
HRB 36809 (AG Nürnberg), Geschäftsführer: Felix Imendörffer

^ permalink raw reply	[flat|nested] 14+ messages in thread

* Re: [RFC PATCH v2 7/7] nvme: Add durable name for dev_printk
  2020-05-13 23:04   ` Keith Busch
@ 2020-05-14 17:13     ` Tony Asleson
  2020-05-14 17:20       ` Keith Busch
  0 siblings, 1 reply; 14+ messages in thread
From: Tony Asleson @ 2020-05-14 17:13 UTC (permalink / raw)
  To: Keith Busch; +Cc: linux-scsi, linux-block

On 5/13/20 6:04 PM, Keith Busch wrote:
> On Wed, May 13, 2020 at 04:36:21PM -0500, Tony Asleson wrote:
>> +static int dev_to_nvme_durable_name(const struct device *dev, char *buf, size_t len)
>> +{
>> +	char serial[128];
>> +	ssize_t serial_len = wwid_show((struct device *)dev, NULL, serial);
> 
> wwid_show() can generate a serial larger than 128 bytes.

Looking at this again

return sprintf(buf, "nvme.%04x-%*phN-%*phN-%08x\n", 	
    subsys->vendor_id,
    serial_len, subsys->serial,
    model_len, subsys->model,
    subsys->ns_id);

'nvme.' = 5
vendor_id = 4
'-' = 1
serial (20 * 2) = 40
'-' = 1
model (40 * 2) = 80
'-' = 1
ns_id = 8
'\n' = 1

5 + 4 + 1 + 40 + 1 + 80 + 1 + 8 + 1 = 141

Does this match your understanding?

My mistake was thinking each byte of SN and Model = 1 character in
output, instead of 2.

This will also require the buffer used in dev_vprintk_emit to be quite a
bit bigger to accommodate max size.

>> +
>> +	if (serial_len > 0 && serial_len < len) {
>> +		serial_len -= 1;  // Remove the '\n' from the string
> 
> Comments in this driver should use the /* */ style.

OK, will revise.

> 
>> +		strncpy(buf, serial, serial_len);
>> +		return serial_len;
>> +	}
>> +	return 0;
>> +}
> 

Thanks
-Tony


^ permalink raw reply	[flat|nested] 14+ messages in thread

* Re: [RFC PATCH v2 7/7] nvme: Add durable name for dev_printk
  2020-05-14 17:13     ` Tony Asleson
@ 2020-05-14 17:20       ` Keith Busch
  0 siblings, 0 replies; 14+ messages in thread
From: Keith Busch @ 2020-05-14 17:20 UTC (permalink / raw)
  To: Tony Asleson; +Cc: linux-scsi, linux-block

On Thu, May 14, 2020 at 12:13:36PM -0500, Tony Asleson wrote:
> On 5/13/20 6:04 PM, Keith Busch wrote:
> > On Wed, May 13, 2020 at 04:36:21PM -0500, Tony Asleson wrote:
> >> +static int dev_to_nvme_durable_name(const struct device *dev, char *buf, size_t len)
> >> +{
> >> +	char serial[128];
> >> +	ssize_t serial_len = wwid_show((struct device *)dev, NULL, serial);
> > 
> > wwid_show() can generate a serial larger than 128 bytes.
> 
> Looking at this again
> 
> return sprintf(buf, "nvme.%04x-%*phN-%*phN-%08x\n", 	
>     subsys->vendor_id,
>     serial_len, subsys->serial,
>     model_len, subsys->model,
>     subsys->ns_id);
> 
> 'nvme.' = 5
> vendor_id = 4
> '-' = 1
> serial (20 * 2) = 40
> '-' = 1
> model (40 * 2) = 80
> '-' = 1
> ns_id = 8
> '\n' = 1
> 
> 5 + 4 + 1 + 40 + 1 + 80 + 1 + 8 + 1 = 141
> 
> Does this match your understanding?

Yep, that looks like the correct max possible length. I didn't actually
count it out, but I just knew it could be larger than 128. :)

^ permalink raw reply	[flat|nested] 14+ messages in thread

* Re: [RFC PATCH v2 5/7] ata_dev_printk: Use dev_printk
  2020-05-14  5:53   ` Hannes Reinecke
@ 2020-05-14 18:03     ` Tony Asleson
       [not found]       ` <CGME20200626135627eucas1p2d68eb5853f90bc636faab69149fbe02c@eucas1p2.samsung.com>
  0 siblings, 1 reply; 14+ messages in thread
From: Tony Asleson @ 2020-05-14 18:03 UTC (permalink / raw)
  To: Hannes Reinecke, linux-scsi, linux-block, James Bottomley

On 5/14/20 12:53 AM, Hannes Reinecke wrote:
> On 5/13/20 11:36 PM, Tony Asleson wrote:
>> Utilize the dev_printk function which will add structured data
>> to the log message.
>>
>> Signed-off-by: Tony Asleson <tasleson@redhat.com>
>> ---
>>   drivers/ata/libata-core.c | 10 +++++++---
>>   1 file changed, 7 insertions(+), 3 deletions(-)
>>
>> diff --git a/drivers/ata/libata-core.c b/drivers/ata/libata-core.c
>> index 42c8728f6117..16978d615a17 100644
>> --- a/drivers/ata/libata-core.c
>> +++ b/drivers/ata/libata-core.c
>> @@ -7301,6 +7301,7 @@ EXPORT_SYMBOL(ata_link_printk);
>>   void ata_dev_printk(const struct ata_device *dev, const char *level,
>>               const char *fmt, ...)
>>   {
>> +    const struct device *gendev;
>>       struct va_format vaf;
>>       va_list args;
>>   @@ -7309,9 +7310,12 @@ void ata_dev_printk(const struct ata_device
>> *dev, const char *level,
>>       vaf.fmt = fmt;
>>       vaf.va = &args;
>>   -    printk("%sata%u.%02u: %pV",
>> -           level, dev->link->ap->print_id, dev->link->pmp + dev->devno,
>> -           &vaf);
>> +    gendev = (dev->sdev) ? &dev->sdev->sdev_gendev : &dev->tdev;
>> +
>> +    dev_printk(level, gendev, "ata%u.%02u: %pV",
>> +            dev->link->ap->print_id,
>> +            dev->link->pmp + dev->devno,
>> +            &vaf);
>>         va_end(args);
>>   }
>>
> That is wrong.
> dev_printk() will already prefix the logging message with the device
> name, so we'll end up having the name printed twice.

It certainly could be. Early in boot when &dev->sdev->sdev_gendev ==
NULL and &dev->tdev is used we get

dev1.0: ata1.00: configured for UDMA/100

later when &dev->sdev->sdev_gendev != NULL we get

sd 1:0:0:0: [sdb] 209715200 512-byte logical blocks: (107 GB/100 GiB)

to clarify, your point is dev1.0 is redundant as ata1.00 exists in the
message?


In the block layer print_req_error we get:

block sdb: blk_update_request: I/O error, dev sdb, sector 10000 op
0x0:(READ) flags 0x80700 phys_seg 4 prio class 0

Which seems a bit more redundant.

I've been trying to be careful to not change the human readable portion
of the message, so not to disturb all the log scraping tools that exist
mining errors.  Maybe this is the wrong approach?  In my original patch
series I brought back printk_emit so that I could add the structured
data without introducing changes in the message text output.  James
Bottomley suggested using dev_printk which certainly made things
cleaner, but it does add the prefix.


Thanks,
Tony


^ permalink raw reply	[flat|nested] 14+ messages in thread

* Re: Re: [RFC PATCH v2 5/7] ata_dev_printk: Use dev_printk
       [not found]       ` <CGME20200626135627eucas1p2d68eb5853f90bc636faab69149fbe02c@eucas1p2.samsung.com>
@ 2020-06-26 13:56         ` Bartlomiej Zolnierkiewicz
  0 siblings, 0 replies; 14+ messages in thread
From: Bartlomiej Zolnierkiewicz @ 2020-06-26 13:56 UTC (permalink / raw)
  To: tasleson; +Cc: Hannes Reinecke, linux-scsi, linux-block, James Bottomley


On 5/14/20 8:03 PM, Tony Asleson wrote:
> On 5/14/20 12:53 AM, Hannes Reinecke wrote:
>> On 5/13/20 11:36 PM, Tony Asleson wrote:
>>> Utilize the dev_printk function which will add structured data
>>> to the log message.
>>>
>>> Signed-off-by: Tony Asleson <tasleson@redhat.com>
>>> ---
>>>   drivers/ata/libata-core.c | 10 +++++++---
>>>   1 file changed, 7 insertions(+), 3 deletions(-)
>>>
>>> diff --git a/drivers/ata/libata-core.c b/drivers/ata/libata-core.c
>>> index 42c8728f6117..16978d615a17 100644
>>> --- a/drivers/ata/libata-core.c
>>> +++ b/drivers/ata/libata-core.c
>>> @@ -7301,6 +7301,7 @@ EXPORT_SYMBOL(ata_link_printk);
>>>   void ata_dev_printk(const struct ata_device *dev, const char *level,
>>>               const char *fmt, ...)
>>>   {
>>> +    const struct device *gendev;
>>>       struct va_format vaf;
>>>       va_list args;
>>>   @@ -7309,9 +7310,12 @@ void ata_dev_printk(const struct ata_device
>>> *dev, const char *level,
>>>       vaf.fmt = fmt;
>>>       vaf.va = &args;
>>>   -    printk("%sata%u.%02u: %pV",
>>> -           level, dev->link->ap->print_id, dev->link->pmp + dev->devno,
>>> -           &vaf);
>>> +    gendev = (dev->sdev) ? &dev->sdev->sdev_gendev : &dev->tdev;
>>> +
>>> +    dev_printk(level, gendev, "ata%u.%02u: %pV",
>>> +            dev->link->ap->print_id,
>>> +            dev->link->pmp + dev->devno,
>>> +            &vaf);
>>>         va_end(args);
>>>   }
>>>
>> That is wrong.
>> dev_printk() will already prefix the logging message with the device
>> name, so we'll end up having the name printed twice.
> 
> It certainly could be. Early in boot when &dev->sdev->sdev_gendev ==
> NULL and &dev->tdev is used we get
> 
> dev1.0: ata1.00: configured for UDMA/100
> 
> later when &dev->sdev->sdev_gendev != NULL we get
> 
> sd 1:0:0:0: [sdb] 209715200 512-byte logical blocks: (107 GB/100 GiB)

This one comes from the SCSI layer.

From libata we get i.e.:

sd 1:0:0:0: ata2.00: exception Emask 0x0 SAct 0x800000 SErr 0x800000
action 0x6 frozen

instead of

ata2.00: exception Emask 0x0 SAct 0x800000 SErr 0x800000 action 0x6 frozen

> to clarify, your point is dev1.0 is redundant as ata1.00 exists in the
> message?
> 
> 
> In the block layer print_req_error we get:
> 
> block sdb: blk_update_request: I/O error, dev sdb, sector 10000 op
> 0x0:(READ) flags 0x80700 phys_seg 4 prio class 0

I think it should be modified to not include dev any longer: 

block sdb: blk_update_request: I/O error, sector 10000 op
0x0:(READ) flags 0x80700 phys_seg 4 prio class 0

but it is up to Jens to make a final decision on that.

> Which seems a bit more redundant.

Yes but it is a debug message visible only on error while for libata
_all_ messages are now changed.

Best regards,
--
Bartlomiej Zolnierkiewicz
Samsung R&D Institute Poland
Samsung Electronics

> I've been trying to be careful to not change the human readable portion
> of the message, so not to disturb all the log scraping tools that exist
> mining errors.  Maybe this is the wrong approach?  In my original patch
> series I brought back printk_emit so that I could add the structured
> data without introducing changes in the message text output.  James
> Bottomley suggested using dev_printk which certainly made things
> cleaner, but it does add the prefix.
> 
> 
> Thanks,
> Tony
> 

^ permalink raw reply	[flat|nested] 14+ messages in thread

end of thread, back to index

Thread overview: 14+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2020-05-13 21:36 [RFC PATCH v2 0/7] Add persistent durable identifier to storage log messages Tony Asleson
2020-05-13 21:36 ` [RFC PATCH v2 1/7] struct device: Add function callback durable_name Tony Asleson
2020-05-13 21:36 ` [RFC PATCH v2 2/7] create_syslog_header: Add durable name Tony Asleson
2020-05-13 21:36 ` [RFC PATCH v2 3/7] print_req_error: Use dev_printk Tony Asleson
2020-05-13 21:36 ` [RFC PATCH v2 4/7] buffer_io_error: " Tony Asleson
2020-05-13 21:36 ` [RFC PATCH v2 5/7] ata_dev_printk: " Tony Asleson
2020-05-14  5:53   ` Hannes Reinecke
2020-05-14 18:03     ` Tony Asleson
     [not found]       ` <CGME20200626135627eucas1p2d68eb5853f90bc636faab69149fbe02c@eucas1p2.samsung.com>
2020-06-26 13:56         ` Bartlomiej Zolnierkiewicz
2020-05-13 21:36 ` [RFC PATCH v2 6/7] scsi: Add durable_name for dev_printk Tony Asleson
2020-05-13 21:36 ` [RFC PATCH v2 7/7] nvme: Add durable name " Tony Asleson
2020-05-13 23:04   ` Keith Busch
2020-05-14 17:13     ` Tony Asleson
2020-05-14 17:20       ` Keith Busch

Linux-Block Archive on lore.kernel.org

Archives are clonable:
	git clone --mirror https://lore.kernel.org/linux-block/0 linux-block/git/0.git

	# If you have public-inbox 1.1+ installed, you may
	# initialize and index your mirror using the following commands:
	public-inbox-init -V2 linux-block linux-block/ https://lore.kernel.org/linux-block \
		linux-block@vger.kernel.org
	public-inbox-index linux-block

Example config snippet for mirrors

Newsgroup available over NNTP:
	nntp://nntp.lore.kernel.org/org.kernel.vger.linux-block


AGPL code for this site: git clone https://public-inbox.org/public-inbox.git