[RFC 0/9] Add persistent durable identifier to storage log messages

[RFC 0/9] Add persistent durable identifier to storage log messages

[Tony Asleson]

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:

# journalctl "_KERNEL_DURABLE_NAME"="t10.ATA QEMU HARDDISK QM00005" \
> | cut -c 25- | fmt -t
...
l: sd 0:0:0:0: [sda] 125829120 512-byte logical blocks: (64.4 GB/60.0 GiB)
l: sd 0:0:0:0: Attached scsi generic sg0 type 0
l: sd 0:0:0:0: [sda] Write Protect is off
l: sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
l: sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't
            support DPO or FUA
l: sd 0:0:0:0: [sda] Attached SCSI disk
l: sata1.00: exception Emask 0x0 SAct 0x2000000 SErr 0x2000000 action
            0x6 frozen
l: sata1.00: failed command: READ FPDMA QUEUED
l: sata1.00: cmd 60/08:c8:08:98:53/00:00:05:00:00/40 tag 25 ncq dma 4096
            in res 40/00:00:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
l: sata1.00: status: { DRDY }
l: sata1.00: configured for UDMA/100
l: sata1.00: device reported invalid CHS sector 0
l: sd 0:0:0:0: [sda] tag#25 FAILED Result: hostbyte=DID_OK
            driverbyte=DRIVER_SENSE
l: sd 0:0:0:0: [sda] tag#25 Sense Key : Illegal Request [current]
l: sd 0:0:0:0: [sda] tag#25 Add. Sense: Unaligned write command
l: sd 0:0:0:0: [sda] tag#25 CDB: Read(10) 28 00 05 53 98 08 00 00 08 00
l: blk_update_request: I/O error, dev sda, sector 89364488 op 0x0:(READ)
            flags 0x80700 phys_seg 1 prio class 0
l: XFS (sda5): Mounting V5 Filesystem
l: XFS (sda5): Ending clean mount
l: XFS (sda5): Unmounting Filesystem
l: sata1.00: exception Emask 0x0 SAct 0x200000 SErr 0x200000 action
            0x6 frozen
l: sata1.00: failed command: READ FPDMA QUEUED
l: sata1.00: cmd 60/08:a8:08:98:53/00:00:05:00:00/40 tag 21 ncq dma 4096
            in res 40/00:ff:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
l: sata1.00: status: { DRDY }
l: sata1.00: configured for UDMA/100
l: sd 0:0:0:0: [sda] tag#21 FAILED Result: hostbyte=DID_OK
            driverbyte=DRIVER_SENSE
l: sd 0:0:0:0: [sda] tag#21 Sense Key : Illegal Request [current]
l: sd 0:0:0:0: [sda] tag#21 Add. Sense: Unaligned write command
l: sd 0:0:0:0: [sda] tag#21 CDB: Read(10) 28 00 05 53 98 08 00 00 08 00
l: blk_update_request: I/O error, dev sda, sector 89364488 op 0x0:(READ)
            flags 0x80700 phys_seg 1 prio class 0
l: sata1.00: exception Emask 0x0 SAct 0x20 SErr 0x20 action 0x6 frozen
l: sata1.00: failed command: READ FPDMA QUEUED
l: sata1.00: cmd 60/08:28:08:98:53/00:00:05:00:00/40 tag 5 ncq dma 4096
            in res 40/00:ff:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
l: sata1.00: status: { DRDY }
l: sata1.00: configured for UDMA/100
l: sata1.00: exception Emask 0x0 SAct 0x200000 SErr 0x200000 action
            0x6 frozen
l: sata1.00: failed command: READ FPDMA QUEUED
l: sata1.00: cmd 60/08:a8:08:98:53/00:00:05:00:00/40 tag 21 ncq dma 4096
            in res 40/00:ff:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
l: sata1.00: status: { DRDY }
l: sata1.00: configured for UDMA/100
l: sata1.00: NCQ disabled due to excessive errors
l: sata1.00: exception Emask 0x0 SAct 0x40000 SErr 0x40000 action
            0x6 frozen
l: sata1.00: failed command: READ FPDMA QUEUED
l: sata1.00: cmd 60/08:90:08:98:53/00:00:05:00:00/40 tag 18 ncq dma 4096
            in res 40/00:ff:00:00:00/00:00:00:00:00/00 Emask 0x4 (timeout)
l: sata1.00: status: { DRDY }
l: sata1.00: configured for UDMA/100
l: XFS (sda5): Mounting V5 Filesystem
l: XFS (sda5): Ending clean mount
l: XFS (sda5): Unmounting Filesystem

This change is incomplete.  With the plethora of different logging
techniques utilized in the kernel for different drivers, file systems,
etc. 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/

The series is based on 5.4.

-Tony

Tony Asleson (9):
  lib/string: Add function to trim duplicate WS
  printk: Bring back printk_emit
  printk: Add printk_emit_ratelimited macro
  struct device_type: Add function callback durable_name
  block: Add support functions for persistent durable name
  create_syslog_header: Add durable name
  print_req_error: Add persistent durable name
  ata_dev_printk: Add durable name to output
  __xfs_printk: Add durable name to output

 block/blk-core.c           | 11 ++++++++++-
 drivers/ata/libata-core.c  | 26 +++++++++++++++++++++++---
 drivers/base/core.c        | 33 +++++++++++++++++++++++++++++++++
 drivers/scsi/scsi_lib.c    | 20 ++++++++++++++++++++
 drivers/scsi/scsi_sysfs.c  |  1 +
 fs/xfs/xfs_message.c       | 17 +++++++++++++++++
 include/linux/device.h     |  4 ++++
 include/linux/printk.h     | 17 +++++++++++++++++
 include/linux/string.h     |  2 ++
 include/scsi/scsi_device.h |  3 +++
 kernel/printk/printk.c     | 15 +++++++++++++++
 lib/string.c               | 35 +++++++++++++++++++++++++++++++++++
 12 files changed, 180 insertions(+), 4 deletions(-)

-- 
2.21.0

[RFC 1/9] lib/string: Add function to trim duplicate WS

[Tony Asleson]

Adds function strim_dupe which trims leading & trailing whitespace and
duplicate adjacent.  Initial use case is to shorten T10 storage IDs.

Signed-off-by: Tony Asleson <tasleson@redhat.com>
---
 include/linux/string.h |  2 ++
 lib/string.c           | 35 +++++++++++++++++++++++++++++++++++
 2 files changed, 37 insertions(+)

diff --git a/include/linux/string.h b/include/linux/string.h
index b6ccdc2c7f02..bcca6bfab6ab 100644
--- a/include/linux/string.h
+++ b/include/linux/string.h
@@ -72,6 +72,8 @@ extern char * __must_check skip_spaces(const char *);
 
 extern char *strim(char *);
 
+extern size_t strim_dupe(char *s);
+
 static inline __must_check char *strstrip(char *str)
 {
 	return strim(str);
diff --git a/lib/string.c b/lib/string.c
index 08ec58cc673b..1186cce1f66b 100644
--- a/lib/string.c
+++ b/lib/string.c
@@ -515,6 +515,41 @@ char *strim(char *s)
 }
 EXPORT_SYMBOL(strim);
 
+/**
+ * Removes leading and trailing whitespace and removes duplicate
+ * adjacent whitespace in a string, modifies string in place.
+ * @s The %NUL-terminated string to have spaces removed
+ * Returns the new length
+ */
+size_t strim_dupe(char *s)
+{
+	size_t ret = 0;
+	char *w = s;
+	char *p;
+
+	/*
+	 * This will remove all leading and duplicate adjacent, but leave
+	 * 1 space at the end if one or more are present.
+	 */
+	for (p = s; *p != '\0'; ++p) {
+		if (!isspace(*p) || (p != s && !isspace(*(p - 1)))) {
+			*w = *p;
+			++w;
+			ret += 1;
+		}
+	}
+
+	*w = '\0';
+
+	/* Take off the last character if it's a space too */
+	if (ret && isspace(*(w - 1))) {
+		ret--;
+		*(w - 1) = '\0';
+	}
+	return ret;
+}
+EXPORT_SYMBOL(strim_dupe);
+
 #ifndef __HAVE_ARCH_STRLEN
 /**
  * strlen - Find the length of a string
-- 
2.21.0

[RFC 2/9] printk: Bring back printk_emit

[Tony Asleson]

Needed for adding structured logging in a number of different areas.

Signed-off-by: Tony Asleson <tasleson@redhat.com>
---
 include/linux/printk.h |  5 +++++
 kernel/printk/printk.c | 15 +++++++++++++++
 2 files changed, 20 insertions(+)

diff --git a/include/linux/printk.h b/include/linux/printk.h
index c09d67edda3a..06c3ba5b695e 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -167,6 +167,11 @@ int vprintk_emit(int facility, int level,
 asmlinkage __printf(1, 0)
 int vprintk(const char *fmt, va_list args);
 
+asmlinkage __printf(5, 6) __cold
+int printk_emit(int facility, int level,
+		const char *dict, size_t dictlen,
+		const char *fmt, ...);
+
 asmlinkage __printf(1, 2) __cold
 int printk(const char *fmt, ...);
 
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index ca65327a6de8..8d7be8c9bb08 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2009,6 +2009,21 @@ asmlinkage int vprintk(const char *fmt, va_list args)
 }
 EXPORT_SYMBOL(vprintk);
 
+asmlinkage int printk_emit(int facility, int level,
+			   const char *dict, size_t dictlen,
+			   const char *fmt, ...)
+{
+	va_list args;
+	int r;
+
+	va_start(args, fmt);
+	r = vprintk_emit(facility, level, dict, dictlen, fmt, args);
+	va_end(args);
+
+	return r;
+}
+EXPORT_SYMBOL(printk_emit);
+
 int vprintk_default(const char *fmt, va_list args)
 {
 	int r;
-- 
2.21.0

[RFC 3/9] printk: Add printk_emit_ratelimited macro

[Tony Asleson]

Needed so we can add structured data to the block layer
logging.

Signed-off-by: Tony Asleson <tasleson@redhat.com>
---
 include/linux/printk.h | 12 ++++++++++++
 1 file changed, 12 insertions(+)

diff --git a/include/linux/printk.h b/include/linux/printk.h
index 06c3ba5b695e..dd41b79e6f06 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -172,6 +172,18 @@ int printk_emit(int facility, int level,
 		const char *dict, size_t dictlen,
 		const char *fmt, ...);
 
+#define printk_emit_ratelimited(facility, level,			\
+		dict, dict_len, fmt, ...)				\
+({									\
+	static DEFINE_RATELIMIT_STATE(_ers,				\
+				      DEFAULT_RATELIMIT_INTERVAL,	\
+				      DEFAULT_RATELIMIT_BURST);		\
+									\
+	if (__ratelimit(&_ers))						\
+		printk_emit(facility, level,				\
+				dict, dict_len, fmt, ##__VA_ARGS__);	\
+})
+
 asmlinkage __printf(1, 2) __cold
 int printk(const char *fmt, ...);
 
-- 
2.21.0

[RFC 4/9] struct device_type: Add function callback durable_name

[Tony Asleson]

Function callback to be used in logging functions to write a persistent
durable name to the supplied character buffer.  This will be used to add
structured key-value data to log messages.

Signed-off-by: Tony Asleson <tasleson@redhat.com>
---
 include/linux/device.h | 2 ++
 1 file changed, 2 insertions(+)

diff --git a/include/linux/device.h b/include/linux/device.h
index 297239a08bb7..dd4ac8db5f57 100644
--- a/include/linux/device.h
+++ b/include/linux/device.h
@@ -799,6 +799,8 @@ struct device_type {
 	void (*release)(struct device *dev);
 
 	const struct dev_pm_ops *pm;
+
+	int (*durable_name)(const struct device *dev, char *buff, size_t len);
 };
 
 /* interface for exporting device attributes */
-- 
2.21.0

[RFC 5/9] block: Add support functions for persistent durable name

[Tony Asleson]

Add functions to retrieve and build durable name string into supplied
buffer for functions that log using struct device and struct scsi_device.

Signed-off-by: Tony Asleson <tasleson@redhat.com>
---
 drivers/base/core.c        | 24 ++++++++++++++++++++++++
 drivers/scsi/scsi_lib.c    | 20 ++++++++++++++++++++
 drivers/scsi/scsi_sysfs.c  |  1 +
 include/linux/device.h     |  2 ++
 include/scsi/scsi_device.h |  3 +++
 5 files changed, 50 insertions(+)

diff --git a/drivers/base/core.c b/drivers/base/core.c
index 7bd9cd366d41..93cc1c45e9d3 100644
--- a/drivers/base/core.c
+++ b/drivers/base/core.c
@@ -2009,6 +2009,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->type && dev->type->durable_name) {
+		tmp = snprintf(buffer, len, "DURABLE_NAME=");
+		if (tmp < len) {
+			dlen = dev->type->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/drivers/scsi/scsi_lib.c b/drivers/scsi/scsi_lib.c
index 91c007d26c1e..f22e59253d9d 100644
--- a/drivers/scsi/scsi_lib.c
+++ b/drivers/scsi/scsi_lib.c
@@ -3120,3 +3120,23 @@ int scsi_vpd_tpg_id(struct scsi_device *sdev, int *rel_id)
 	return group_id;
 }
 EXPORT_SYMBOL(scsi_vpd_tpg_id);
+
+int dev_to_scsi_durable_name(const struct device *dev, char *buf, size_t len)
+{
+	return scsi_durable_name(to_scsi_device(dev), buf, len);
+}
+EXPORT_SYMBOL(dev_to_scsi_durable_name);
+
+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 = strim_dupe(buf) + 1;
+	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 6d7362e7367e..ee5b8197916f 100644
--- a/drivers/scsi/scsi_sysfs.c
+++ b/drivers/scsi/scsi_sysfs.c
@@ -1560,6 +1560,7 @@ static struct device_type scsi_dev_type = {
 	.name =		"scsi_device",
 	.release =	scsi_device_dev_release,
 	.groups =	scsi_sdev_attr_groups,
+	.durable_name = dev_to_scsi_durable_name,
 };
 
 void scsi_sysfs_device_initialize(struct scsi_device *sdev)
diff --git a/include/linux/device.h b/include/linux/device.h
index dd4ac8db5f57..566f6be6ee0d 100644
--- a/include/linux/device.h
+++ b/include/linux/device.h
@@ -1350,6 +1350,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)
 {
diff --git a/include/scsi/scsi_device.h b/include/scsi/scsi_device.h
index 202f4d6a4342..1cb35e10f54a 100644
--- a/include/scsi/scsi_device.h
+++ b/include/scsi/scsi_device.h
@@ -455,6 +455,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.21.0

[RFC 6/9] create_syslog_header: Add durable name

[Tony Asleson]

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 | 9 +++++++++
 1 file changed, 9 insertions(+)

diff --git a/drivers/base/core.c b/drivers/base/core.c
index 93cc1c45e9d3..57b5f5cd29fc 100644
--- a/drivers/base/core.c
+++ b/drivers/base/core.c
@@ -3318,6 +3318,15 @@ create_syslog_header(const struct device *dev, char *hdr, size_t hdrlen)
 				"DEVICE=+%s:%s", subsys, dev_name(dev));
 	}
 
+	if (dev->type && dev->type->durable_name) {
+		int dlen;
+
+		dlen = dev_durable_name(dev, hdr + (pos + 1),
+					hdrlen - (pos + 1));
+		if (dlen)
+			pos += dlen + 1;
+	}
+
 	if (pos >= hdrlen)
 		goto overflow;
 
-- 
2.21.0

[RFC 7/9] print_req_error: Add persistent durable name

[Tony Asleson]

Add persistent durable name to errors that occur in block mid layer.

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

diff --git a/block/blk-core.c b/block/blk-core.c
index d5e668ec751b..a0171a7c6535 100644
--- a/block/blk-core.c
+++ b/block/blk-core.c
@@ -211,11 +211,20 @@ static void print_req_error(struct request *req, blk_status_t status,
 		const char *caller)
 {
 	int idx = (__force int)status;
+	char dict[128];
+	int dict_len = 0;
 
 	if (WARN_ON_ONCE(idx >= ARRAY_SIZE(blk_errors)))
 		return;
 
-	printk_ratelimited(KERN_ERR
+	if (req->rq_disk) {
+		dict_len = dev_durable_name(
+				disk_to_dev(req->rq_disk)->parent,
+				dict,
+				sizeof(dict));
+	}
+
+	printk_emit_ratelimited(0, LOGLEVEL_ERR, dict, dict_len,
 		"%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.21.0

[RFC 8/9] ata_dev_printk: Add durable name to output

[Tony Asleson]

If we have a durable name we will add to output, else
we will default to existing message output format.

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

diff --git a/drivers/ata/libata-core.c b/drivers/ata/libata-core.c
index 28c492be0a57..b57a74cfb529 100644
--- a/drivers/ata/libata-core.c
+++ b/drivers/ata/libata-core.c
@@ -7249,6 +7249,9 @@ EXPORT_SYMBOL(ata_link_printk);
 void ata_dev_printk(const struct ata_device *dev, const char *level,
 		    const char *fmt, ...)
 {
+	char dict[128];
+	int dict_len = 0;
+
 	struct va_format vaf;
 	va_list args;
 
@@ -7257,9 +7260,26 @@ 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);
+	if (dev->sdev) {
+		dict_len = dev_durable_name(
+			&dev->sdev->sdev_gendev,
+			dict,
+			sizeof(dict));
+	}
+
+	if (dict_len > 0) {
+		printk_emit(0, level[1] - '0', dict, dict_len,
+				"sata%u.%02u: %pV",
+				dev->link->ap->print_id,
+				dev->link->pmp + dev->devno,
+				&vaf);
+	} else {
+		printk("%sata%u.%02u: %pV",
+			level,
+			dev->link->ap->print_id,
+			dev->link->pmp + dev->devno,
+			&vaf);
+	}
 
 	va_end(args);
 }
-- 
2.21.0

[RFC 9/9] __xfs_printk: Add durable name to output

[Tony Asleson]

Add persistent durable name to xfs messages so we can
correlate them with other messages for the same block
device.

Signed-off-by: Tony Asleson <tasleson@redhat.com>
---
 fs/xfs/xfs_message.c | 17 +++++++++++++++++
 1 file changed, 17 insertions(+)

diff --git a/fs/xfs/xfs_message.c b/fs/xfs/xfs_message.c
index 9804efe525a9..8447cdd985b4 100644
--- a/fs/xfs/xfs_message.c
+++ b/fs/xfs/xfs_message.c
@@ -20,6 +20,23 @@ __xfs_printk(
 	const struct xfs_mount	*mp,
 	struct va_format	*vaf)
 {
+	char dict[128];
+	int dict_len = 0;
+
+	if (mp && mp->m_super && mp->m_super->s_bdev &&
+		mp->m_super->s_bdev->bd_disk) {
+		dict_len = dev_durable_name(
+			disk_to_dev(mp->m_super->s_bdev->bd_disk)->parent,
+			dict,
+			sizeof(dict));
+		if (dict_len) {
+			printk_emit(
+				0, level[1] - '0', dict, dict_len,
+				"XFS (%s): %pV\n",  mp->m_fsname, vaf);
+			return;
+		}
+	}
+
 	if (mp && mp->m_fsname) {
 		printk("%sXFS (%s): %pV\n", level, mp->m_fsname, vaf);
 		return;
-- 
2.21.0

Re: [RFC 1/9] lib/string: Add function to trim duplicate WS

[Matthew Wilcox]

On Mon, Dec 23, 2019 at 04:55:50PM -0600, Tony Asleson wrote:
> +/**
> + * Removes leading and trailing whitespace and removes duplicate
> + * adjacent whitespace in a string, modifies string in place.
> + * @s The %NUL-terminated string to have spaces removed
> + * Returns the new length
> + */

This isn't good kernel-doc.  See Documentation/doc-guide/kernel-doc.rst
Compile with W=1 to get the format checked.

> +size_t strim_dupe(char *s)
> +{
> +	size_t ret = 0;
> +	char *w = s;
> +	char *p;
> +
> +	/*
> +	 * This will remove all leading and duplicate adjacent, but leave
> +	 * 1 space at the end if one or more are present.
> +	 */
> +	for (p = s; *p != '\0'; ++p) {
> +		if (!isspace(*p) || (p != s && !isspace(*(p - 1)))) {
> +			*w = *p;
> +			++w;
> +			ret += 1;
> +		}
> +	}

I'd be tempted to do ...

	size_t ret = 0;
	char *w = s;
	bool last_space = false;

	do {
		bool this_space = isspace(*s);

		if (!this_space || !last_space) {
			*w++ = *s;
			ret++;
		}
		s++;
		last_space = this_space;
	} while (s[-1] != '\0');

> +	/* Take off the last character if it's a space too */
> +	if (ret && isspace(*(w - 1))) {
> +		ret--;
> +		*(w - 1) = '\0';
> +	}
> +	return ret;
> +}
> +EXPORT_SYMBOL(strim_dupe);
> +
>  #ifndef __HAVE_ARCH_STRLEN
>  /**
>   * strlen - Find the length of a string
> -- 
> 2.21.0
> 

Re: [RFC 0/9] Add persistent durable identifier to storage log messages

[James Bottomley]

On Mon, 2019-12-23 at 16:55 -0600, Tony Asleson wrote:
> 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.

I understand why, and using the best VPD identifier we have seems fine.
 However, we're trying to dump printk in favour of dev_printk and its
ilk, so resurrecting printk_emit instead of using dev_printk_emit looks
a bit retrograde.  It does seem that ata_dev_printk should really be
using dev_printk ... not sure about the block case.

You also have a couple of items which could be shorter, but I'll reply
to the individual patches.

James

Re: [RFC 6/9] create_syslog_header: Add durable name

[James Bottomley]

On Mon, 2019-12-23 at 16:55 -0600, Tony Asleson wrote:
> 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 | 9 +++++++++
>  1 file changed, 9 insertions(+)
> 
> diff --git a/drivers/base/core.c b/drivers/base/core.c
> index 93cc1c45e9d3..57b5f5cd29fc 100644
> --- a/drivers/base/core.c
> +++ b/drivers/base/core.c
> @@ -3318,6 +3318,15 @@ create_syslog_header(const struct device *dev,
> char *hdr, size_t hdrlen)
>  				"DEVICE=+%s:%s", subsys,
> dev_name(dev));
>  	}
>  
> +	if (dev->type && dev->type->durable_name) {
> +		int dlen;
> +
> +		dlen = dev_durable_name(dev, hdr + (pos + 1),
> +					hdrlen - (pos + 1));
> +		if (dlen)
> +			pos += dlen + 1;
> +	}
> +

dev_durable_name already returns zero if either dev->type or dev->type-
>durable_name are NULL, so the if() above is pointless.

James

Re: [RFC 8/9] ata_dev_printk: Add durable name to output

[James Bottomley]

On Mon, 2019-12-23 at 16:55 -0600, Tony Asleson wrote:
> If we have a durable name we will add to output, else
> we will default to existing message output format.
> 
> Signed-off-by: Tony Asleson <tasleson@redhat.com>
> ---
>  drivers/ata/libata-core.c | 26 +++++++++++++++++++++++---
>  1 file changed, 23 insertions(+), 3 deletions(-)
> 
> diff --git a/drivers/ata/libata-core.c b/drivers/ata/libata-core.c
> index 28c492be0a57..b57a74cfb529 100644
> --- a/drivers/ata/libata-core.c
> +++ b/drivers/ata/libata-core.c
> @@ -7249,6 +7249,9 @@ EXPORT_SYMBOL(ata_link_printk);
>  void ata_dev_printk(const struct ata_device *dev, const char *level,
>  		    const char *fmt, ...)
>  {
> +	char dict[128];
> +	int dict_len = 0;
> +
>  	struct va_format vaf;
>  	va_list args;
>  
> @@ -7257,9 +7260,26 @@ 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);
> +	if (dev->sdev) {
> +		dict_len = dev_durable_name(
> +			&dev->sdev->sdev_gendev,
> +			dict,
> +			sizeof(dict));
> +	}
> +
> +	if (dict_len > 0) {
> +		printk_emit(0, level[1] - '0', dict, dict_len,
> +				"sata%u.%02u: %pV",
> +				dev->link->ap->print_id,
> +				dev->link->pmp + dev->devno,
> +				&vaf);
> +	} else {
> +		printk("%sata%u.%02u: %pV",
> +			level,
> +			dev->link->ap->print_id,
> +			dev->link->pmp + dev->devno,
> +			&vaf);
> +	}

As I said, I think ata_dev_printk should expand to dev_printk, which
would render all the above unnecessary, but just in case there's a
problem, printk_emit() with a dict_len == 0 is directly equivalent to
printk() so the whole if (dict_len > 0) is unnecessary.

James

Re: [RFC 1/9] lib/string: Add function to trim duplicate WS

[Tony Asleson]

On 12/23/19 5:28 PM, Matthew Wilcox wrote:
> On Mon, Dec 23, 2019 at 04:55:50PM -0600, Tony Asleson wrote:
>> +/**
>> + * Removes leading and trailing whitespace and removes duplicate
>> + * adjacent whitespace in a string, modifies string in place.
>> + * @s The %NUL-terminated string to have spaces removed
>> + * Returns the new length
>> + */
> 
> This isn't good kernel-doc.  See Documentation/doc-guide/kernel-doc.rst
> Compile with W=1 to get the format checked.

Indeed, I'll correct it.

>> +size_t strim_dupe(char *s)
>> +{
>> +	size_t ret = 0;
>> +	char *w = s;
>> +	char *p;
>> +
>> +	/*
>> +	 * This will remove all leading and duplicate adjacent, but leave
>> +	 * 1 space at the end if one or more are present.
>> +	 */
>> +	for (p = s; *p != '\0'; ++p) {
>> +		if (!isspace(*p) || (p != s && !isspace(*(p - 1)))) {
>> +			*w = *p;
>> +			++w;
>> +			ret += 1;
>> +		}
>> +	}
> 
> I'd be tempted to do ...
> 
> 	size_t ret = 0;
> 	char *w = s;
> 	bool last_space = false;
> 
> 	do {
> 		bool this_space = isspace(*s);
> 
> 		if (!this_space || !last_space) {
> 			*w++ = *s;
> 			ret++;
> 		}
> 		s++;
> 		last_space = this_space;
> 	} while (s[-1] != '\0');

That leaves a starting and trailing WS, how about something like this?

size_t strim_dupe(char *s)
{
	size_t ret = 0;
	char *w = s;
	bool last_space = false;

	do {
		bool this_space = isspace(*s);
		if (!this_space || (!last_space && ret)) {
			*w++ = *s;
			ret++;
		}
		s++;
		last_space = this_space;
	} while (s[-1] != '\0');

	if (ret > 1 && isspace(w[-2])) {
		w[-2] = '\0';
		ret--;
	}

	ret--;
	return ret;
}

Thanks
-Tony

Re: [RFC 0/9] Add persistent durable identifier to storage log messages

[Tony Asleson]

On 12/23/19 6:50 PM, James Bottomley wrote:
> On Mon, 2019-12-23 at 16:55 -0600, Tony Asleson wrote:
>> 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.
> 
> I understand why, and using the best VPD identifier we have seems fine.
>  However, we're trying to dump printk in favour of dev_printk and its
> ilk, so resurrecting printk_emit instead of using dev_printk_emit looks
> a bit retrograde.  It does seem that ata_dev_printk should really be
> using dev_printk ... not sure about the block case.

I'll re-work the patch series to move towards dev_printk_emit.


Thanks
-Tony

Re: [RFC 6/9] create_syslog_header: Add durable name

[Tony Asleson]

On 12/23/19 6:54 PM, James Bottomley wrote:
> On Mon, 2019-12-23 at 16:55 -0600, Tony Asleson wrote:
>> 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 | 9 +++++++++
>>  1 file changed, 9 insertions(+)
>>
>> diff --git a/drivers/base/core.c b/drivers/base/core.c
>> index 93cc1c45e9d3..57b5f5cd29fc 100644
>> --- a/drivers/base/core.c
>> +++ b/drivers/base/core.c
>> @@ -3318,6 +3318,15 @@ create_syslog_header(const struct device *dev,
>> char *hdr, size_t hdrlen)
>>  				"DEVICE=+%s:%s", subsys,
>> dev_name(dev));
>>  	}
>>  
>> +	if (dev->type && dev->type->durable_name) {
>> +		int dlen;
>> +
>> +		dlen = dev_durable_name(dev, hdr + (pos + 1),
>> +					hdrlen - (pos + 1));
>> +		if (dlen)
>> +			pos += dlen + 1;
>> +	}
>> +
> 
> dev_durable_name already returns zero if either dev->type or dev->type-
>> durable_name are NULL, so the if() above is pointless.

Indeed, will remove redundant checks in patch re-work.

Thanks
-Tony

Re: [RFC 1/9] lib/string: Add function to trim duplicate WS

[Tony Asleson]

On 1/2/20 4:52 PM, Tony Asleson wrote:
> On 12/23/19 5:28 PM, Matthew Wilcox wrote:
>> On Mon, Dec 23, 2019 at 04:55:50PM -0600, Tony Asleson wrote:
>>> +/**
>>> + * Removes leading and trailing whitespace and removes duplicate
>>> + * adjacent whitespace in a string, modifies string in place.
>>> + * @s The %NUL-terminated string to have spaces removed
>>> + * Returns the new length
>>> + */
>>
>> This isn't good kernel-doc.  See Documentation/doc-guide/kernel-doc.rst
>> Compile with W=1 to get the format checked.
> 
> Indeed, I'll correct it.
> 
>>> +size_t strim_dupe(char *s)
>>> +{
>>> +	size_t ret = 0;
>>> +	char *w = s;
>>> +	char *p;
>>> +
>>> +	/*
>>> +	 * This will remove all leading and duplicate adjacent, but leave
>>> +	 * 1 space at the end if one or more are present.
>>> +	 */
>>> +	for (p = s; *p != '\0'; ++p) {
>>> +		if (!isspace(*p) || (p != s && !isspace(*(p - 1)))) {
>>> +			*w = *p;
>>> +			++w;
>>> +			ret += 1;
>>> +		}
>>> +	}
>>
>> I'd be tempted to do ...
>>
>> 	size_t ret = 0;
>> 	char *w = s;
>> 	bool last_space = false;
>>
>> 	do {
>> 		bool this_space = isspace(*s);
>>
>> 		if (!this_space || !last_space) {
>> 			*w++ = *s;
>> 			ret++;
>> 		}
>> 		s++;
>> 		last_space = this_space;
>> 	} while (s[-1] != '\0');
> 
> That leaves a starting and trailing WS, how about something like this?
> 
> size_t strim_dupe(char *s)
> {
> 	size_t ret = 0;
> 	char *w = s;
> 	bool last_space = false;
> 
> 	do {
> 		bool this_space = isspace(*s);
> 		if (!this_space || (!last_space && ret)) {Mollie Fitzgerald
> 			*w++ = *s;
> 			ret++;
> 		}
> 		s++;
> 		last_space = this_space;
> 	} while (s[-1] != '\0');
> 
> 	if (ret > 1 && isspace(w[-2])) {
> 		w[-2] = '\0';
> 		ret--;
> 	}
> 
> 	ret--;
> 	return ret;
> }

This function was added so I could strip out extra spaces in the vpd
0x83 string representation, to shorten them before they get added to the
structured syslog message.  I'm starting to think this is a bad idea as
anyone that might want to write some code to use the kernel sysfs entry
for a device and search for it in the syslog would have to perturb the
id string the same way.

I think this change should just be removed from the patch series and
leave the IDs as they are.

If we really wanted a shorter ID, a better approach would be use a hash
of the ID string, but that introduces another level of complexity that
isn't helpful to end users.

-Tony

Re: [RFC 9/9] __xfs_printk: Add durable name to output

[Dave Chinner]

On Mon, Dec 23, 2019 at 04:55:58PM -0600, Tony Asleson wrote:
> Add persistent durable name to xfs messages so we can
> correlate them with other messages for the same block
> device.
> 
> Signed-off-by: Tony Asleson <tasleson@redhat.com>
> ---
>  fs/xfs/xfs_message.c | 17 +++++++++++++++++
>  1 file changed, 17 insertions(+)
> 
> diff --git a/fs/xfs/xfs_message.c b/fs/xfs/xfs_message.c
> index 9804efe525a9..8447cdd985b4 100644
> --- a/fs/xfs/xfs_message.c
> +++ b/fs/xfs/xfs_message.c
> @@ -20,6 +20,23 @@ __xfs_printk(
>  	const struct xfs_mount	*mp,
>  	struct va_format	*vaf)
>  {
> +	char dict[128];
> +	int dict_len = 0;
> +
> +	if (mp && mp->m_super && mp->m_super->s_bdev &&
> +		mp->m_super->s_bdev->bd_disk) {
> +		dict_len = dev_durable_name(
> +			disk_to_dev(mp->m_super->s_bdev->bd_disk)->parent,
> +			dict,
> +			sizeof(dict));
> +		if (dict_len) {
> +			printk_emit(
> +				0, level[1] - '0', dict, dict_len,
> +				"XFS (%s): %pV\n",  mp->m_fsname, vaf);
> +			return;
> +		}
> +	}

NACK on the ground this is a gross hack.

> +
>  	if (mp && mp->m_fsname) {

mp->m_fsname is the name of the device we use everywhere for log
messages, it's set up at mount time so we don't have to do runtime
evaulation of the device name every time we need to emit the device
name in a log message.

So, if you have some sooper speshial new device naming scheme, it
needs to be stored into the struct xfs_mount to replace mp->m_fsname.

And if you have some sooper spehsial new printk API that uses this
new device name, everything XFS emits needs to use it
unconditionally as we do with mp->m_fsname now.

IOWs, this isn't conditional code - it either works for the entire
life of the mount for every message we have to emit with a single
setup call, or the API is broken and needs to be rethought.

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

Re: [RFC 9/9] __xfs_printk: Add durable name to output

[Tony Asleson]

On 1/3/20 8:56 PM, Dave Chinner wrote:
> On Mon, Dec 23, 2019 at 04:55:58PM -0600, Tony Asleson wrote:
>> Add persistent durable name to xfs messages so we can
>> correlate them with other messages for the same block
>> device.
>>
>> Signed-off-by: Tony Asleson <tasleson@redhat.com>
>> ---
>>  fs/xfs/xfs_message.c | 17 +++++++++++++++++
>>  1 file changed, 17 insertions(+)
>>
>> diff --git a/fs/xfs/xfs_message.c b/fs/xfs/xfs_message.c
>> index 9804efe525a9..8447cdd985b4 100644
>> --- a/fs/xfs/xfs_message.c
>> +++ b/fs/xfs/xfs_message.c
>> @@ -20,6 +20,23 @@ __xfs_printk(
>>  	const struct xfs_mount	*mp,
>>  	struct va_format	*vaf)
>>  {
>> +	char dict[128];
>> +	int dict_len = 0;
>> +
>> +	if (mp && mp->m_super && mp->m_super->s_bdev &&
>> +		mp->m_super->s_bdev->bd_disk) {
>> +		dict_len = dev_durable_name(
>> +			disk_to_dev(mp->m_super->s_bdev->bd_disk)->parent,
>> +			dict,
>> +			sizeof(dict));
>> +		if (dict_len) {
>> +			printk_emit(
>> +				0, level[1] - '0', dict, dict_len,
>> +				"XFS (%s): %pV\n",  mp->m_fsname, vaf);
>> +			return;
>> +		}
>> +	}
> 
> NACK on the ground this is a gross hack.

James suggested I utilize dev_printk, which does make things simpler.
Would something like this be acceptable?

diff --git a/fs/xfs/xfs_message.c b/fs/xfs/xfs_message.c
index 9804efe525a9..0738c74a8d3a 100644
--- a/fs/xfs/xfs_message.c
+++ b/fs/xfs/xfs_message.c
@@ -20,11 +20,18 @@ __xfs_printk(
        const struct xfs_mount  *mp,
        struct va_format        *vaf)
 {
+       struct device *dev = NULL;
+
+       if (mp && mp->m_super && mp->m_super->s_bdev &&
+               mp->m_super->s_bdev->bd_disk) {
+               dev = disk_to_dev(mp->m_super->s_bdev->bd_disk)->parent;
+       }
+
        if (mp && mp->m_fsname) {
-               printk("%sXFS (%s): %pV\n", level, mp->m_fsname, vaf);
+               dev_printk(level, dev, "XFS (%s): %pV\n", mp->m_fsname,
vaf);
                return;
        }
-       printk("%sXFS: %pV\n", level, vaf);
+       dev_printk(level, dev, "XFS: %pV\n", vaf);
 }

>> +
>>  	if (mp && mp->m_fsname) {
> 
> mp->m_fsname is the name of the device we use everywhere for log
> messages, it's set up at mount time so we don't have to do runtime
> evaulation of the device name every time we need to emit the device
> name in a log message.
> 
> So, if you have some sooper speshial new device naming scheme, it
> needs to be stored into the struct xfs_mount to replace mp->m_fsname.

I don't think we want to replace mp->m_fsname with the vpd 0x83 device
identifier.  This proposed change is adding a key/value structured data
to the log message for non-ambiguous device identification over time,
not to place the ID in the human readable portion of the message.  The
existing name is useful too, especially when it involves a partition.

> And if you have some sooper spehsial new printk API that uses this
> new device name, everything XFS emits needs to use it
> unconditionally as we do with mp->m_fsname now.
> 
> IOWs, this isn't conditional code - it either works for the entire
> life of the mount for every message we have to emit with a single
> setup call, or the API is broken and needs to be rethought.

I've been wondering why the struct scsi device uses rcu data for the vpd
as I would not think that it would be changing for a specific device.
Perhaps James can shed some light on this?

-Tony

Re: [RFC 9/9] __xfs_printk: Add durable name to output

[Dave Chinner]

On Sun, Jan 05, 2020 at 08:45:00PM -0600, Tony Asleson wrote:
> On 1/3/20 8:56 PM, Dave Chinner wrote:
> > On Mon, Dec 23, 2019 at 04:55:58PM -0600, Tony Asleson wrote:
> >> Add persistent durable name to xfs messages so we can
> >> correlate them with other messages for the same block
> >> device.
> >>
> >> Signed-off-by: Tony Asleson <tasleson@redhat.com>
> >> ---
> >>  fs/xfs/xfs_message.c | 17 +++++++++++++++++
> >>  1 file changed, 17 insertions(+)
> >>
> >> diff --git a/fs/xfs/xfs_message.c b/fs/xfs/xfs_message.c
> >> index 9804efe525a9..8447cdd985b4 100644
> >> --- a/fs/xfs/xfs_message.c
> >> +++ b/fs/xfs/xfs_message.c
> >> @@ -20,6 +20,23 @@ __xfs_printk(
> >>  	const struct xfs_mount	*mp,
> >>  	struct va_format	*vaf)
> >>  {
> >> +	char dict[128];
> >> +	int dict_len = 0;
> >> +
> >> +	if (mp && mp->m_super && mp->m_super->s_bdev &&
> >> +		mp->m_super->s_bdev->bd_disk) {
> >> +		dict_len = dev_durable_name(
> >> +			disk_to_dev(mp->m_super->s_bdev->bd_disk)->parent,
> >> +			dict,
> >> +			sizeof(dict));
> >> +		if (dict_len) {
> >> +			printk_emit(
> >> +				0, level[1] - '0', dict, dict_len,
> >> +				"XFS (%s): %pV\n",  mp->m_fsname, vaf);
> >> +			return;
> >> +		}
> >> +	}
> > 
> > NACK on the ground this is a gross hack.
> 
> James suggested I utilize dev_printk, which does make things simpler.
> Would something like this be acceptable?
> 
> diff --git a/fs/xfs/xfs_message.c b/fs/xfs/xfs_message.c
> index 9804efe525a9..0738c74a8d3a 100644
> --- a/fs/xfs/xfs_message.c
> +++ b/fs/xfs/xfs_message.c
> @@ -20,11 +20,18 @@ __xfs_printk(
>         const struct xfs_mount  *mp,
>         struct va_format        *vaf)
>  {
> +       struct device *dev = NULL;
> +
> +       if (mp && mp->m_super && mp->m_super->s_bdev &&
> +               mp->m_super->s_bdev->bd_disk) {
> +               dev = disk_to_dev(mp->m_super->s_bdev->bd_disk)->parent;
> +       }
> +
>         if (mp && mp->m_fsname) {
> -               printk("%sXFS (%s): %pV\n", level, mp->m_fsname, vaf);
> +               dev_printk(level, dev, "XFS (%s): %pV\n", mp->m_fsname,
> vaf);
>                 return;
>         }
> -       printk("%sXFS: %pV\n", level, vaf);
> +       dev_printk(level, dev, "XFS: %pV\n", vaf);

No, because that's just doing the same thing involving dynamic
extraction of static, unchanging information. Only now we get the
output looking like:

[ts] "<driver string> <dev name>: XFS (<dev name>): <message>"

Or we get:

[ts] "(NULL device *): XFS: <message>"

Both of which don't provide any extra useful information to the
person/script parsing the log message.

Oh, and calling dev_printk() with a null dev pointer is likely to
panic the machine in dev_driver_string().

>  }
> 
> >> +
> >>  	if (mp && mp->m_fsname) {
> > 
> > mp->m_fsname is the name of the device we use everywhere for log
> > messages, it's set up at mount time so we don't have to do runtime
> > evaulation of the device name every time we need to emit the device
> > name in a log message.
> > 
> > So, if you have some sooper speshial new device naming scheme, it
> > needs to be stored into the struct xfs_mount to replace mp->m_fsname.
> 
> I don't think we want to replace mp->m_fsname with the vpd 0x83 device
> identifier.  This proposed change is adding a key/value structured data
> to the log message for non-ambiguous device identification over time,
> not to place the ID in the human readable portion of the message.  The
> existing name is useful too, especially when it involves a partition.

Oh, if that's all you want to do, then why is this identifier needed
in every log message? It does not change over the life of the
filesystem, so it the persistent identifier only needs to be emitted
to the log once at filesystem mount time. i.e.  instead of:

[    2.716841] XFS (dm-0): Mounting V5 Filesystem

It just needs to be:

[    2.716841] XFS (dm-0): Mounting V5 Filesystem on device <persistent dev id>

If you need to do any sort of special "is this the right device"
checking, it needs to be done immediately at mount time so action
can be taken to shutdown the filesystem and unmount the device
immediately before further damage is done....

i.e. once the filesystem is mounted, you've already got a unique and
persistent identifier in the log for the life of the filesystem (the
m_fsname string), so I'm struggling to understand exactly what
problem you are trying to solve by adding redundant information
to every log message.....

> > And if you have some sooper spehsial new printk API that uses this
> > new device name, everything XFS emits needs to use it
> > unconditionally as we do with mp->m_fsname now.
> > 
> > IOWs, this isn't conditional code - it either works for the entire
> > life of the mount for every message we have to emit with a single
> > setup call, or the API is broken and needs to be rethought.
> 
> I've been wondering why the struct scsi device uses rcu data for the vpd
> as I would not think that it would be changing for a specific device.
> Perhaps James can shed some light on this?

The implementation of the in-memory driver vpd data page has no
relationship to the lifetime of the persistent information that
the VPD stores/reports.

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

Re: [RFC 9/9] __xfs_printk: Add durable name to output

[Sweet Tea Dorminy]

> > >> +
> > >>    if (mp && mp->m_fsname) {
> > >
> > > mp->m_fsname is the name of the device we use everywhere for log
> > > messages, it's set up at mount time so we don't have to do runtime
> > > evaulation of the device name every time we need to emit the device
> > > name in a log message.
> > >
> > > So, if you have some sooper speshial new device naming scheme, it
> > > needs to be stored into the struct xfs_mount to replace mp->m_fsname.
> >
> > I don't think we want to replace mp->m_fsname with the vpd 0x83 device
> > identifier.  This proposed change is adding a key/value structured data
> > to the log message for non-ambiguous device identification over time,
> > not to place the ID in the human readable portion of the message.  The
> > existing name is useful too, especially when it involves a partition.
>
> Oh, if that's all you want to do, then why is this identifier needed
> in every log message? It does not change over the life of the
> filesystem, so it the persistent identifier only needs to be emitted
> to the log once at filesystem mount time. i.e.  instead of:
>
> [    2.716841] XFS (dm-0): Mounting V5 Filesystem
>
> It just needs to be:
>
> [    2.716841] XFS (dm-0): Mounting V5 Filesystem on device <persistent dev id>
>
> If you need to do any sort of special "is this the right device"
> checking, it needs to be done immediately at mount time so action
> can be taken to shutdown the filesystem and unmount the device
> immediately before further damage is done....
>
> i.e. once the filesystem is mounted, you've already got a unique and
> persistent identifier in the log for the life of the filesystem (the
> m_fsname string), so I'm struggling to understand exactly what
> problem you are trying to solve by adding redundant information
> to every log message.....
>

Log rotation loses that identifier though; there are plenty of setups
where a mount-time message has been rotated out of all logs by the
time something goes wrong after a month or two.

Re: [RFC 9/9] __xfs_printk: Add durable name to output

[Dave Chinner]

On Mon, Jan 06, 2020 at 07:19:07PM -0500, Sweet Tea Dorminy wrote:
> > > >> +
> > > >>    if (mp && mp->m_fsname) {
> > > >
> > > > mp->m_fsname is the name of the device we use everywhere for log
> > > > messages, it's set up at mount time so we don't have to do runtime
> > > > evaulation of the device name every time we need to emit the device
> > > > name in a log message.
> > > >
> > > > So, if you have some sooper speshial new device naming scheme, it
> > > > needs to be stored into the struct xfs_mount to replace mp->m_fsname.
> > >
> > > I don't think we want to replace mp->m_fsname with the vpd 0x83 device
> > > identifier.  This proposed change is adding a key/value structured data
> > > to the log message for non-ambiguous device identification over time,
> > > not to place the ID in the human readable portion of the message.  The
> > > existing name is useful too, especially when it involves a partition.
> >
> > Oh, if that's all you want to do, then why is this identifier needed
> > in every log message? It does not change over the life of the
> > filesystem, so it the persistent identifier only needs to be emitted
> > to the log once at filesystem mount time. i.e.  instead of:
> >
> > [    2.716841] XFS (dm-0): Mounting V5 Filesystem
> >
> > It just needs to be:
> >
> > [    2.716841] XFS (dm-0): Mounting V5 Filesystem on device <persistent dev id>
> >
> > If you need to do any sort of special "is this the right device"
> > checking, it needs to be done immediately at mount time so action
> > can be taken to shutdown the filesystem and unmount the device
> > immediately before further damage is done....
> >
> > i.e. once the filesystem is mounted, you've already got a unique and
> > persistent identifier in the log for the life of the filesystem (the
> > m_fsname string), so I'm struggling to understand exactly what
> > problem you are trying to solve by adding redundant information
> > to every log message.....
> 
> Log rotation loses that identifier though; there are plenty of setups
> where a mount-time message has been rotated out of all logs by the
> time something goes wrong after a month or two.

At what point months after you've mounted the filesystem do you care
about whether the correct device was mounted or not?

And, for the log rotation case, the filesystem log output already
has a unique, persistent identifier for the life of the mount - the
fsname ("dm-0" in the above example). We don't need to add a new
device identifier to the XFS log messages to solve that problem
because *we've already got a device identifier in the log messages*.

Again - the "is this the right device" information only makes sense
to be checked at mount time. If it was the right device at mount
time, then after months of uptime how would it suddenly become "the
wrong device"? And if it's the wrong device at mount time, then you
need to take action *immediately*, not after using the filesysetms
on the device for months...

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

Re: [RFC 9/9] __xfs_printk: Add durable name to output

[Tony Asleson]

On 1/6/20 7:23 PM, Dave Chinner wrote:
> On Mon, Jan 06, 2020 at 07:19:07PM -0500, Sweet Tea Dorminy wrote:
>>>>>> +
>>>>>>    if (mp && mp->m_fsname) {
>>>>>
>>>>> mp->m_fsname is the name of the device we use everywhere for log
>>>>> messages, it's set up at mount time so we don't have to do runtime
>>>>> evaulation of the device name every time we need to emit the device
>>>>> name in a log message.
>>>>>
>>>>> So, if you have some sooper speshial new device naming scheme, it
>>>>> needs to be stored into the struct xfs_mount to replace mp->m_fsname.
>>>>
>>>> I don't think we want to replace mp->m_fsname with the vpd 0x83 device
>>>> identifier.  This proposed change is adding a key/value structured data
>>>> to the log message for non-ambiguous device identification over time,
>>>> not to place the ID in the human readable portion of the message.  The
>>>> existing name is useful too, especially when it involves a partition.
>>>
>>> Oh, if that's all you want to do, then why is this identifier needed
>>> in every log message? 

The value is we can filter all the messages by the id as they are all
individually identifiable.

The structured data id that the patch series adds is not outputted by
default by journalctl.  Please look at cover letter in patch series for
example filter use.  You can see all the data in the journal entries by
using journalctl -o json-pretty.

One can argue that we are adding a lot of data to each log message as
the VPD data isn't trivial.  This could be mitigated by hashing the VPD
and storing the hash as the ID, but that makes it less user friendly.
However, maybe it should be considered.

>>> It does not change over the life of the
>>> filesystem, so it the persistent identifier only needs to >>> be
emitted to the log once at filesystem mount time. i.e.  >>> instead of:
>>>
>>> [    2.716841] XFS (dm-0): Mounting V5 Filesystem
>>>
>>> It just needs to be:
>>>
>>> [    2.716841] XFS (dm-0): Mounting V5 Filesystem on device <persistent dev id>
>>>
>>> If you need to do any sort of special "is this the right device"
>>> checking, it needs to be done immediately at mount time so action
>>> can be taken to shutdown the filesystem and unmount the device
>>> immediately before further damage is done....
>>>
>>> i.e. once the filesystem is mounted, you've already got a unique and
>>> persistent identifier in the log for the life of the filesystem (the
>>> m_fsname string), so I'm struggling to understand exactly what
>>> problem you are trying to solve by adding redundant information
>>> to every log message.....

m_fsname is only valid for the life of the mount, not the life of the
FS.  Each and every time we reboot, remove/reattach a device the
attachment point may change and thus the m_fsname changes too.  Then the
user or script writer has to figure out what messages go with what
device.  This is true for all the different storage layer messages.
Some layers use sda, sata1.00 or sd 0:0:0:0 and they all refer to the
same device.

We have no unambiguous way today to identify which messages go with what
storage device across reboots and dynamic device re-configuration across
the storage stack.

>>
>> Log rotation loses that identifier though; there are plenty of setups
>> where a mount-time message has been rotated out of all logs by the
>> time something goes wrong after a month or two.
> 
> At what point months after you've mounted the filesystem do you care
> about whether the correct device was mounted or not?

This isn't a question about if the correct device was mounted or not.
It's the question of what actual storage hardware was associated with
the message(s), an association that doesn't change across reboots or
dynamic device reconfiguration or if you move the physical device to
another system.

The cover letter example shows filtered output of one specific device
encountering errors that has an XFS FS.  Without this added ID it would
not be so easy to determine that these messages all belong to the same
device.  In this case the attachment isn't changing, it's the simple
case.  When it does change over time it gets even more difficult.

> And, for the log rotation case, the filesystem log output already
> has a unique, persistent identifier for the life of the mount - the
> fsname ("dm-0" in the above example). We don't need to add a new
> device identifier to the XFS log messages to solve that problem
> because *we've already got a device identifier in the log messages*.

It's very useful to have an ID that persists and identifies across
mounts.  The existing id logging scheme tells you where something is
attached, not what is attached.

> Again - the "is this the right device" information only makes sense
> to be checked at mount time. If it was the right device at mount
> time, then after months of uptime how would it suddenly become "the
> wrong device"? And if it's the wrong device at mount time, then you
> need to take action *immediately*, not after using the filesysetms
> on the device for months...
> 
> Cheers,
> 
> Dave.
> 

Re: [RFC 9/9] __xfs_printk: Add durable name to output

[Dave Chinner]

On Tue, Jan 07, 2020 at 11:01:47AM -0600, Tony Asleson wrote:
> On 1/6/20 7:23 PM, Dave Chinner wrote:
> > On Mon, Jan 06, 2020 at 07:19:07PM -0500, Sweet Tea Dorminy wrote:
> >>>>>> +
> >>>>>>    if (mp && mp->m_fsname) {
> >>>>>
> >>>>> mp->m_fsname is the name of the device we use everywhere for log
> >>>>> messages, it's set up at mount time so we don't have to do runtime
> >>>>> evaulation of the device name every time we need to emit the device
> >>>>> name in a log message.
> >>>>>
> >>>>> So, if you have some sooper speshial new device naming scheme, it
> >>>>> needs to be stored into the struct xfs_mount to replace mp->m_fsname.
> >>>>
> >>>> I don't think we want to replace mp->m_fsname with the vpd 0x83 device
> >>>> identifier.  This proposed change is adding a key/value structured data
> >>>> to the log message for non-ambiguous device identification over time,
> >>>> not to place the ID in the human readable portion of the message.  The
> >>>> existing name is useful too, especially when it involves a partition.
> >>>
> >>> Oh, if that's all you want to do, then why is this identifier needed
> >>> in every log message? 
> 
> The value is we can filter all the messages by the id as they are all
> individually identifiable.

Then what you want is the *filesystem label* or *filesystem UUID*
in the *filesystem log output* to uniquely identify the *filesystem
log output* regardless of the block device identifier the kernel
assigned it's underlying disk.

By trying to use the block device as the source of a persistent
filesytem identifier, you are creating more new problems about
uniqueness than you are solving.  E.g.

- there can be more than one filesystem per block device, so the
  identifier needs to be, at minimum, a {dev_id, partition} tuple.
  The existing bdev name (e.g. sda2) that filesystems emit contain
  this information. The underlying vpd device indentifier does not.

- the filesystem on a device can change (e.g. mkfs), so an unchanged
  vpd identifier does not mean we mounted the same filesystem

- raid devices are made up of multiple physical devices, so using
  device information for persistent identification is problematic,
  especially when devices fail and are replaced with different
  hardware.

- clone a filesystem to a new device to replace a failing disk,
  block device identifier changes but the filesystem doesn't.

Basically, if you need a *persistent filesystem identifier* for
your log messages, then you cannot rely on the underlying device to
provide that. Filesystems already have unique identifiers in them
that can be used for this purpose, and we have mechanisms to allow
users to configure them as well.

IOWs, you're trying to tackle this "filesystem identifier" at the
wrong layer - use the persistent filesystem identifiers to
persitently identify the filesystem across mounts, not some random
block device identifier.

> The structured data id that the patch series adds is not outputted by
> default by journalctl.  Please look at cover letter in patch series for
> example filter use.  You can see all the data in the journal entries by
> using journalctl -o json-pretty.

Yes, I understand that. But my comments about adding redundant
information to the log text output were directed at your suggestiong to
use dev_printk() instead of printk to achieve what you want. That
changes the log text output by prepending device specific strings to
the filesystem output.

> One can argue that we are adding a lot of data to each log message
> as the VPD data isn't trivial.  This could be mitigated by hashing
> the VPD and storing the hash as the ID, but that makes it less
> user friendly.  However, maybe it should be considered.

See above, I don't think the VPD information actually solves the
problem you are seeking to solve.

> >>> It does not change over the life of the filesystem, so it the
> >>> persistent identifier only needs to >>> be
> emitted to the log once at filesystem mount time. i.e.  >>>
> instead of:
> >>>
> >>> [    2.716841] XFS (dm-0): Mounting V5 Filesystem
> >>>
> >>> It just needs to be:
> >>>
> >>> [    2.716841] XFS (dm-0): Mounting V5 Filesystem on device
> >>> <persistent dev id>
> >>>
> >>> If you need to do any sort of special "is this the right
> >>> device" checking, it needs to be done immediately at mount
> >>> time so action can be taken to shutdown the filesystem and
> >>> unmount the device immediately before further damage is
> >>> done....
> >>>
> >>> i.e. once the filesystem is mounted, you've already got a
> >>> unique and persistent identifier in the log for the life of
> >>> the filesystem (the m_fsname string), so I'm struggling to
> >>> understand exactly what problem you are trying to solve by
> >>> adding redundant information to every log message.....
> 
> m_fsname is only valid for the life of the mount, not the life of
> the FS.  Each and every time we reboot, remove/reattach a device
> the attachment point may change and thus the m_fsname changes too.

Well, yes, that's because m_fsname is currently aimed at identifying
the block device that the filesytem is currently mounted on. That's
the block device we *actually care about* when trying to diagnose
problems reported in the log.  From that perspective, I don't want
the log output to change - it contains exactly what we need to
diagnose problems when things go wrong.

But for structured logging, using block device identifiers for the
filesystem identifier is just wrong. If you need new information,
append the UUID from the filesystem to the log message and use that
instead. i.e your original printk_emit() function should pass
mp->m_sb.sb_uuid as the post-message binary filesystem identifier,
not the block device VPD information.

If you need to convert the filesystem uuid to a block device, then
you can just go look up /dev/disk/by-uuid/ and follow the link the
filesystem uuid points to....

> > And, for the log rotation case, the filesystem log output
> > already has a unique, persistent identifier for the life of the
> > mount - the fsname ("dm-0" in the above example). We don't need
> > to add a new device identifier to the XFS log messages to solve
> > that problem because *we've already got a device identifier in
> > the log messages*.
> 
> It's very useful to have an ID that persists and identifies across
> mounts.  The existing id logging scheme tells you where something
> is attached, not what is attached.

Yup, that's what the filesystem labels and UUIDs provide. We've been
using them for this purpose for a long, long time.

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

Re: [RFC 9/9] __xfs_printk: Add durable name to output

[Tony Asleson]

On 1/7/20 8:10 PM, Dave Chinner wrote:
> On Tue, Jan 07, 2020 at 11:01:47AM -0600, Tony Asleson wrote:
>> On 1/6/20 7:23 PM, Dave Chinner wrote:
>>> On Mon, Jan 06, 2020 at 07:19:07PM -0500, Sweet Tea Dorminy wrote:
>>>>>>>> +
>>>>>>>>    if (mp && mp->m_fsname) {
>>>>>>>
>>>>>>> mp->m_fsname is the name of the device we use everywhere for log
>>>>>>> messages, it's set up at mount time so we don't have to do runtime
>>>>>>> evaulation of the device name every time we need to emit the device
>>>>>>> name in a log message.
>>>>>>>
>>>>>>> So, if you have some sooper speshial new device naming scheme, it
>>>>>>> needs to be stored into the struct xfs_mount to replace mp->m_fsname.
>>>>>>
>>>>>> I don't think we want to replace mp->m_fsname with the vpd 0x83 device
>>>>>> identifier.  This proposed change is adding a key/value structured data
>>>>>> to the log message for non-ambiguous device identification over time,
>>>>>> not to place the ID in the human readable portion of the message.  The
>>>>>> existing name is useful too, especially when it involves a partition.
>>>>>
>>>>> Oh, if that's all you want to do, then why is this identifier needed
>>>>> in every log message? 
>>
>> The value is we can filter all the messages by the id as they are all
>> individually identifiable.
> 
> Then what you want is the *filesystem label* or *filesystem UUID*
> in the *filesystem log output* to uniquely identify the *filesystem
> log output* regardless of the block device identifier the kernel
> assigned it's underlying disk.
> 
> By trying to use the block device as the source of a persistent
> filesytem identifier, you are creating more new problems about
> uniqueness than you are solving.  E.g.
> 
> - there can be more than one filesystem per block device, so the
>   identifier needs to be, at minimum, a {dev_id, partition} tuple.
>   The existing bdev name (e.g. sda2) that filesystems emit contain
>   this information. The underlying vpd device indentifier does not.

We are not removing any existing information, we are adding.

I think all the file systems should include their FS UUID in the FS log
messages too, but that is not part of the problem we are trying to solve.

> - the filesystem on a device can change (e.g. mkfs), so an unchanged
>   vpd identifier does not mean we mounted the same filesystem
> 
> - raid devices are made up of multiple physical devices, so using
>   device information for persistent identification is problematic,
>   especially when devices fail and are replaced with different
>   hardware.

For the desired use cases its not problematic.  With this we would have
a definitive id of which messages go with which disk.  We know if the
disk is still present in the system or if it went away and came back or
if it showed up in some other system.  We also have a definitive ID of
which disk to yank from the system.

> - clone a filesystem to a new device to replace a failing disk,
>   block device identifier changes but the filesystem doesn't.

Yes, and now you have log messages for two filesystems which exist on
different physical hardware which you cannot distinguish, if you
leverage the FS UUID in the log messages.

> Basically, if you need a *persistent filesystem identifier* for
> your log messages, then you cannot rely on the underlying device to
> provide that. Filesystems already have unique identifiers in them
> that can be used for this purpose, and we have mechanisms to allow
> users to configure them as well.

I'm not advocating for a persistent filesystem id.  Lets outline some
user stories to help illustrate.

I found a few log messages from 4 months ago, device sdk was
experiencing media errors.  How do I view the log messages for that
device in my entire log history, through the entire storage stack from
device driver to FS?

I have a storage device that is intermittently failing, was this disk
used anywhere else in our data center?  Was it experiencing issues
before?  Is it in the same batch of disks we bought together that has
been experiencing higher failure rates?

I have 2 identical external USB storage devices, I bought them at the
same time.  They get moved around in my home for backup and sometimes I
take one with when traveling.  I occasionally use dd to backup one
device to the other when the data is important and I haven't backed it
up anywhere else.  I found log messages that shows a device is
intermittently having a problem, which one is it so I can contact the
vendor for warranty replacement?


Trying to solve these questions can be difficult with the existing
convention of logging messages that look like:

blk_update_request: I/O error, dev sda, sector 89364488 op 0x0:(READ)
flags 0x80700 phys_seg 1 prio class 0

The user has to systematically and methodically go through the logs
trying to deduce what the identifier was referring to at the time of the
error.  This isn't trivial and virtually impossible at times depending
on circumstances.

> IOWs, you're trying to tackle this "filesystem identifier" at the
> wrong layer - use the persistent filesystem identifiers to
> persitently identify the filesystem across mounts, not some random
> block device identifier.

The vpd 0x83 is not random, it's the best thing we have to identify a
piece of storage hardware.  One issue is it's not available for every
device.  We need to find suitable ID's for those devices too.  We aren't
trying to persistently identify the FS, we are trying to persistently
identify which messages go with which device.

>> The structured data id that the patch series adds is not outputted by
>> default by journalctl.  Please look at cover letter in patch series for
>> example filter use.  You can see all the data in the journal entries by
>> using journalctl -o json-pretty.
> 
> Yes, I understand that. But my comments about adding redundant
> information to the log text output were directed at your suggestiong to
> use dev_printk() instead of printk to achieve what you want. That
> changes the log text output by prepending device specific strings to
> the filesystem output.
> 
>> One can argue that we are adding a lot of data to each log message
>> as the VPD data isn't trivial.  This could be mitigated by hashing
>> the VPD and storing the hash as the ID, but that makes it less
>> user friendly.  However, maybe it should be considered.
> 
> See above, I don't think the VPD information actually solves the
> problem you are seeking to solve.
> 
>>>>> It does not change over the life of the filesystem, so it the
>>>>> persistent identifier only needs to >>> be
>> emitted to the log once at filesystem mount time. i.e.  >>>
>> instead of:
>>>>>
>>>>> [    2.716841] XFS (dm-0): Mounting V5 Filesystem
>>>>>
>>>>> It just needs to be:
>>>>>
>>>>> [    2.716841] XFS (dm-0): Mounting V5 Filesystem on device
>>>>> <persistent dev id>
>>>>>
>>>>> If you need to do any sort of special "is this the right
>>>>> device" checking, it needs to be done immediately at mount
>>>>> time so action can be taken to shutdown the filesystem and
>>>>> unmount the device immediately before further damage is
>>>>> done....
>>>>>
>>>>> i.e. once the filesystem is mounted, you've already got a
>>>>> unique and persistent identifier in the log for the life of
>>>>> the filesystem (the m_fsname string), so I'm struggling to
>>>>> understand exactly what problem you are trying to solve by
>>>>> adding redundant information to every log message.....
>>
>> m_fsname is only valid for the life of the mount, not the life of
>> the FS.  Each and every time we reboot, remove/reattach a device
>> the attachment point may change and thus the m_fsname changes too.
> 
> Well, yes, that's because m_fsname is currently aimed at identifying
> the block device that the filesytem is currently mounted on. That's
> the block device we *actually care about* when trying to diagnose
> problems reported in the log.  From that perspective, I don't want
> the log output to change - it contains exactly what we need to
> diagnose problems when things go wrong.
> 
> But for structured logging, using block device identifiers for the
> filesystem identifier is just wrong. If you need new information,
> append the UUID from the filesystem to the log message and use that
> instead. i.e your original printk_emit() function should pass
> mp->m_sb.sb_uuid as the post-message binary filesystem identifier,
> not the block device VPD information.
> 
> If you need to convert the filesystem uuid to a block device, then
> you can just go look up /dev/disk/by-uuid/ and follow the link the
> filesystem uuid points to....
> 
>>> And, for the log rotation case, the filesystem log output
>>> already has a unique, persistent identifier for the life of the
>>> mount - the fsname ("dm-0" in the above example). We don't need
>>> to add a new device identifier to the XFS log messages to solve
>>> that problem because *we've already got a device identifier in
>>> the log messages*.
>>
>> It's very useful to have an ID that persists and identifies across
>> mounts.  The existing id logging scheme tells you where something
>> is attached, not what is attached.
> 
> Yup, that's what the filesystem labels and UUIDs provide. We've been
> using them for this purpose for a long, long time.

FS UUIDs exist on the media, they can be duplicated, destroyed or fail
to be read up due to media errors.  They do serve an important function,
esp. mounting, but they don't address the use cases described above.

Re: [RFC 9/9] __xfs_printk: Add durable name to output

[Alasdair G Kergon]

On Wed, Jan 08, 2020 at 10:53:13AM -0600, Tony Asleson wrote:
> We are not removing any existing information, we are adding.

A difficulty with this approach is:  Where do you stop when your storage
configuration is complicated and changing?  Do you add the complete
relevant part of the storage stack configuration to every storage
message in the kernel so that it is easy to search later?

Or do you catch the messages in userspace and add some of this
information there before sending them on to your favourite log message
database?  (ref. peripety, various rsyslog extensions)

> I think all the file systems should include their FS UUID in the FS log
> messages too, but that is not part of the problem we are trying to solve.

Each layer (subsystem) should already be tagging its messages in an
easy-to-parse way so that all those relating to the same object (e.g.
filesystem instance, disk) at its level of the stack can easily be
matched together later.  Where this doesn't already happen, we should
certainly be fixing that as it's a pre-requisite for any sensible
post-processing: As long as the right information got recorded, it can
all be joined together on demand later by some userspace software.
 
> The user has to systematically and methodically go through the logs
> trying to deduce what the identifier was referring to at the time of the
> error.  This isn't trivial and virtually impossible at times depending
> on circumstances.

So how about logging what these identifiers reference at different times
in a way that is easy to query later?

Come to think of it, we already get uevents when the references change,
and udev rules even already now create neat "by-*" links for us.  Maybe
we just need to log better what udev is actually already doing?

Then we could reproduce what the storage configuration looked like at
any particular time in the past to provide the missing context for
the identifiers in the log messages.

                    ---------------------
 
Which seems like an appropriate time to introduce storage-logger.

    https://github.com/lvmteam/storage-logger

    Fedora rawhide packages:
      https://copr.fedorainfracloud.org/coprs/agk/storage-logger/ 

The goal of this particular project is to maintain a record of the
storage configuration as it changes over time.  It should provide a
quick way to check the state of a system at a specified time in the
past.

The initial logging implementation is triggered by storage uevents and
consists of two components:

1. A new udev rule file, 99-zzz-storage-logger.rules, which runs after
all the other rules have run and invokes:

2. A script, udev_storage_logger.sh, that captures relevant
information about devices that changed and stores it in the system
journal.

The effect is to log the data from relevant uevents plus some
supplementary information (including device-mapper tables, for example).
It does not yet handle filesystem-related events.

Two methods to query the data are offered:

1. journalctl
Data is tagged with the identifier UDEVLOG and retrievable as
key-value pairs.
  journalctl -t UDEVLOG --output verbose
  journalctl -t UDEVLOG --output json
    --since 'YYYY-MM-DD HH:MM:SS' 
    --until 'YYYY-MM-DD HH:MM:SS'
  journalctl -t UDEVLOG --output verbose
    --output-fields=PERSISTENT_STORAGE_ID,MAJOR,MINOR
     PERSISTENT_STORAGE_ID=dm-name-vg1-lvol0

2. lsblkj  [appended j for journal]
This lsblk wrapper reprocesses the logged uevents to reconstruct a
dummy system environment that "looks like" the system did at a
specified earlier time and then runs lsblk against it.

Yes, I'm looking for feedback to help to decide whether or not it's
worth developing this any further.

Alasdair

Re: [RFC 9/9] __xfs_printk: Add durable name to output

[Dave Chinner]

On Thu, Jan 09, 2020 at 01:41:17AM +0000, Alasdair G Kergon wrote:
> On Wed, Jan 08, 2020 at 10:53:13AM -0600, Tony Asleson wrote:
> > We are not removing any existing information, we are adding.
> 
> A difficulty with this approach is:  Where do you stop when your storage
> configuration is complicated and changing?  Do you add the complete
> relevant part of the storage stack configuration to every storage
> message in the kernel so that it is easy to search later?
> 
> Or do you catch the messages in userspace and add some of this
> information there before sending them on to your favourite log message
> database?  (ref. peripety, various rsyslog extensions)
> 
> > I think all the file systems should include their FS UUID in the FS log
> > messages too, but that is not part of the problem we are trying to solve.
> 
> Each layer (subsystem) should already be tagging its messages in an
> easy-to-parse way so that all those relating to the same object (e.g.
> filesystem instance, disk) at its level of the stack can easily be
> matched together later.  Where this doesn't already happen, we should
> certainly be fixing that as it's a pre-requisite for any sensible
> post-processing: As long as the right information got recorded, it can
> all be joined together on demand later by some userspace software.

*nod*

That was the essence of my suggestion that the filesystem mount log
notification emits it's persistent identifier. If you need it to be
logged, that's where the verbose identifier output should be....

> > The user has to systematically and methodically go through the logs
> > trying to deduce what the identifier was referring to at the time of the
> > error.  This isn't trivial and virtually impossible at times depending
> > on circumstances.
> 
> So how about logging what these identifiers reference at different times
> in a way that is easy to query later?
> 
> Come to think of it, we already get uevents when the references change,
> and udev rules even already now create neat "by-*" links for us.  Maybe
> we just need to log better what udev is actually already doing?

Right, this is essentially what I've been trying to point out - I
even used the by-uuid links as an example of how the filesystem is
persistently identified by existing system boot infrastructure. :)

> Then we could reproduce what the storage configuration looked like at
> any particular time in the past to provide the missing context for
> the identifiers in the log messages.
> 
>                     ---------------------
>  
> Which seems like an appropriate time to introduce storage-logger.
> 
>     https://github.com/lvmteam/storage-logger
> 
>     Fedora rawhide packages:
>       https://copr.fedorainfracloud.org/coprs/agk/storage-logger/ 
> 
> The goal of this particular project is to maintain a record of the
> storage configuration as it changes over time.  It should provide a
> quick way to check the state of a system at a specified time in the
> past.
> 
> The initial logging implementation is triggered by storage uevents and
> consists of two components:
> 
> 1. A new udev rule file, 99-zzz-storage-logger.rules, which runs after
> all the other rules have run and invokes:
> 
> 2. A script, udev_storage_logger.sh, that captures relevant
> information about devices that changed and stores it in the system
> journal.
> 
> The effect is to log the data from relevant uevents plus some
> supplementary information (including device-mapper tables, for example).
> It does not yet handle filesystem-related events.

There are very few filesystem uevents issued that you could log,
anyway. Certainly nothing standardised across filesystems....

> Two methods to query the data are offered:
> 
> 1. journalctl
> Data is tagged with the identifier UDEVLOG and retrievable as
> key-value pairs.
>   journalctl -t UDEVLOG --output verbose
>   journalctl -t UDEVLOG --output json
>     --since 'YYYY-MM-DD HH:MM:SS' 
>     --until 'YYYY-MM-DD HH:MM:SS'
>   journalctl -t UDEVLOG --output verbose
>     --output-fields=PERSISTENT_STORAGE_ID,MAJOR,MINOR
>      PERSISTENT_STORAGE_ID=dm-name-vg1-lvol0
> 
> 2. lsblkj  [appended j for journal]
> This lsblk wrapper reprocesses the logged uevents to reconstruct a
> dummy system environment that "looks like" the system did at a
> specified earlier time and then runs lsblk against it.

Yeah, and if you add the equivalent of 'lsblk -f' then you also get
the fs UUID to identify the filesystem on the block device at a
given time....

> Yes, I'm looking for feedback to help to decide whether or not it's
> worth developing this any further.

This seems like a more flexible approach to me - it allows for
text-based system loggers a hook to capture this device
information, too, and hence implement their own post-processing
scripts to provide the same lifetime information.

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

Re: [RFC 9/9] __xfs_printk: Add durable name to output

[Alasdair G Kergon]

On Fri, Jan 10, 2020 at 10:22:44AM +1100, Dave Chinner wrote:
> Yeah, and if you add the equivalent of 'lsblk -f' then you also get
> the fs UUID to identify the filesystem on the block device at a
> given time....

The UUID usually already gets recorded and displayed:

# lsblkj -f --until "2020-01-09 22:00:00"
NAME                             FSTYPE      FSVER LABEL UUID                                   FSAVAIL FSUSE% MOUNTPOINT
sda                                                                                                            
├─sda1                           xfs                     78524ad6-6445-4bb6-840b-194871231274   
...

(It's also capturing something simple for mountpoint when it can, but so far that's
only visible with journalctl.)
 
Alasdair

Re: [RFC 9/9] __xfs_printk: Add durable name to output

[Tony Asleson]

On 1/8/20 7:41 PM, Alasdair G Kergon wrote:
> The goal of this particular project is to maintain a record of the
> storage configuration as it changes over time.  It should provide a
> quick way to check the state of a system at a specified time in the
> past.

This helps with one aspect of the problem, it leaves a bread crumb which
states that at this point in time /dev/sda was the attachment point for
some device, eg. wwn-0x5002538844580000.

> The initial logging implementation is triggered by storage uevents and
> consists of two components:
> 
> 1. A new udev rule file, 99-zzz-storage-logger.rules, which runs after
> all the other rules have run and invokes:
> 
> 2. A script, udev_storage_logger.sh, that captures relevant
> information about devices that changed and stores it in the system
> journal.
> 
> The effect is to log the data from relevant uevents plus some
> supplementary information (including device-mapper tables, for example).
> It does not yet handle filesystem-related events.
> 
> Two methods to query the data are offered:
> 
> 1. journalctl
> Data is tagged with the identifier UDEVLOG and retrievable as
> key-value pairs.
>   journalctl -t UDEVLOG --output verbose
>   journalctl -t UDEVLOG --output json
>     --since 'YYYY-MM-DD HH:MM:SS' 
>     --until 'YYYY-MM-DD HH:MM:SS'
>   journalctl -t UDEVLOG --output verbose
>     --output-fields=PERSISTENT_STORAGE_ID,MAJOR,MINOR
>      PERSISTENT_STORAGE_ID=dm-name-vg1-lvol0
> 
> 2. lsblkj  [appended j for journal]
> This lsblk wrapper reprocesses the logged uevents to reconstruct a
> dummy system environment that "looks like" the system did at a
> specified earlier time and then runs lsblk against it.

You've outlined how to view and filter on the added data and how to
figure out what the configuration looked like a some point in the past,
that adds one more piece of the puzzle.

However, how would a user simply show all the log messages for a
specific device over time?  It looks like journalctl would need to have
logic added to make this a seamless user experience, yes?

Perhaps I'm missing something that makes the outlined use case above work?