[RFC v3 0/2] generate uevent for SCSI sense code

[RFC v3 0/2] generate uevent for SCSI sense code

[Song Liu]

This change is to follow up our discussion on event log for media
management during LSF/MM 2017.

Changes from RFC v2:
1. change rate limit of events from per device to per SCSI host
2. fix bugs from feedbacks

Please kindly let me know your thoughts on this.

Thanks,
Song

Song Liu (2):
  scsi: generate uevent for SCSI sense code
  scsi: add rate limit to scsi sense code uevent

 drivers/scsi/Kconfig       | 14 +++++++++++
 drivers/scsi/hosts.c       |  4 ++++
 drivers/scsi/scsi_error.c  | 59 ++++++++++++++++++++++++++++++++++++++++++++++
 drivers/scsi/scsi_lib.c    | 58 ++++++++++++++++++++++++++++++++++++++++++++-
 drivers/scsi/scsi_sysfs.c  | 51 +++++++++++++++++++++++++++++++++++++++
 include/scsi/scsi_common.h |  6 +++++
 include/scsi/scsi_device.h | 27 ++++++++++++++++++++-
 include/scsi/scsi_host.h   | 13 ++++++++++
 8 files changed, 230 insertions(+), 2 deletions(-)

--
2.9.3

[RFC v3 1/2] scsi: generate uevent for SCSI sense code

[Song Liu]

This patch adds capability for SCSI layer to generate uevent for SCSI
sense code. The feature is gated by CONFIG_SCSI_SENSE_UEVENT.

We can configure which sense keys generate uevent for each device
through sysfs entry sense_event_filter, which is a bitmap of
"sense keys to generate uevent" For example, the following enables
uevent for MEDIUM_ERROR (0x03) and HARDWARE_ERROR (0x04) on scsi
drive sdc:

    echo 0x000c > /sys/block/sdc/device/sense_event_filter

Here is an example output captured by udevadm:

KERNEL[587.353177] change   /devices/pci0000:00/XXXXXXXXXX
ACTION=change
CDB=\x88\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x08\x00\x00
DEVPATH=/devices/pci0000:00/0000:00:01.0/0000:01:00.0/host6/XXXXXX
DEVTYPE=scsi_device
DRIVER=sd
MODALIAS=scsi:t-0x00
SDEV_SENSE=1
SENSE_BUFFER=\x72\x03\x11\x14\x00\x00\x00\x34\x00\x0a\x80 ....
SENSE_CODE=3/11/14
SEQNUM=4796
SUBSYSTEM=scsi

Signed-off-by: Song Liu <songliubraving@fb.com>
---
 drivers/scsi/Kconfig       | 14 +++++++++++
 drivers/scsi/scsi_error.c  | 43 ++++++++++++++++++++++++++++++++++
 drivers/scsi/scsi_lib.c    | 58 +++++++++++++++++++++++++++++++++++++++++++++-
 drivers/scsi/scsi_sysfs.c  | 51 ++++++++++++++++++++++++++++++++++++++++
 include/scsi/scsi_common.h |  6 +++++
 include/scsi/scsi_device.h | 27 ++++++++++++++++++++-
 6 files changed, 197 insertions(+), 2 deletions(-)

diff --git a/drivers/scsi/Kconfig b/drivers/scsi/Kconfig
index d384f4f..0fb672b 100644
--- a/drivers/scsi/Kconfig
+++ b/drivers/scsi/Kconfig
@@ -226,6 +226,20 @@ config SCSI_LOGGING
 	  there should be no noticeable performance impact as long as you have
 	  logging turned off.
 
+config SCSI_SENSE_UEVENT
+	bool "SCSI sense code logging"
+	depends on SCSI
+	default n
+	---help---
+	  This turns on uevent for SCSI sense code.
+
+	  You can configure which sense keys generate uevent for each device
+	  through sysfs entry sense_event_filter. For example, the following
+	  enables uevent for MEDIUM_ERROR (0x03) and HARDWARE_ERROR (0x04)
+	  on scsi drive sdc:
+
+	  echo 0x000c > /sys/block/sdc/device/sense_event_filter
+
 config SCSI_SCAN_ASYNC
 	bool "Asynchronous SCSI scanning"
 	depends on SCSI
diff --git a/drivers/scsi/scsi_error.c b/drivers/scsi/scsi_error.c
index ac31964..b8ef869 100644
--- a/drivers/scsi/scsi_error.c
+++ b/drivers/scsi/scsi_error.c
@@ -426,6 +426,48 @@ static void scsi_report_sense(struct scsi_device *sdev,
 	}
 }
 
+/*
+ * generate uevent when receiving sense code from device
+ */
+static void scsi_send_sense_uevent(struct scsi_device *sdev,
+				   struct scsi_cmnd *scmd,
+				   struct scsi_sense_hdr *sshdr)
+{
+#ifdef CONFIG_SCSI_SENSE_UEVENT
+	struct scsi_event *evt;
+	unsigned char sb_len;
+
+	if (!test_bit(sshdr->sense_key & 0xf,
+		      &sdev->sense_event_filter))
+		return;
+	evt = sdev_evt_alloc(SDEV_EVT_SCSI_SENSE, GFP_ATOMIC);
+	if (!evt)
+		return;
+
+	evt->sense_evt_data.cmnd = kzalloc(scmd->cmd_len, GFP_ATOMIC);
+	if (!evt->sense_evt_data.cmnd)
+		goto alloc_cmd_fail;
+
+	sb_len = scsi_sense_data_length(scmd->sense_buffer);
+
+	evt->sense_evt_data.sense_buffer = kzalloc(sb_len, GFP_ATOMIC);
+	if (!evt->sense_evt_data.sense_buffer)
+		goto alloc_sense_fail;
+
+	evt->sense_evt_data.cmd_len = scmd->cmd_len;
+	evt->sense_evt_data.sb_len = sb_len;
+	memcpy(evt->sense_evt_data.cmnd, scmd->cmnd, scmd->cmd_len);
+	memcpy(evt->sense_evt_data.sense_buffer, scmd->sense_buffer, sb_len);
+
+	sdev_evt_send(sdev, evt);
+	return;
+alloc_sense_fail:
+	kfree(evt->sense_evt_data.cmnd);
+alloc_cmd_fail:
+	kfree(evt);
+#endif
+}
+
 /**
  * scsi_check_sense - Examine scsi cmd sense
  * @scmd:	Cmd to have sense checked.
@@ -446,6 +488,7 @@ int scsi_check_sense(struct scsi_cmnd *scmd)
 		return FAILED;	/* no valid sense data */
 
 	scsi_report_sense(sdev, &sshdr);
+	scsi_send_sense_uevent(sdev, scmd, &sshdr);
 
 	if (scsi_sense_is_deferred(&sshdr))
 		return NEEDS_RETRY;
diff --git a/drivers/scsi/scsi_lib.c b/drivers/scsi/scsi_lib.c
index 41c19c7..67cc0fb 100644
--- a/drivers/scsi/scsi_lib.c
+++ b/drivers/scsi/scsi_lib.c
@@ -2677,7 +2677,15 @@ EXPORT_SYMBOL(scsi_device_set_state);
 static void scsi_evt_emit(struct scsi_device *sdev, struct scsi_event *evt)
 {
 	int idx = 0;
-	char *envp[3];
+	char *envp[5];	/* SDEV_EVT_SCSI_SENSE needs most entries (4) */
+#ifdef CONFIG_SCSI_SENSE_UEVENT
+	char *buf = NULL;
+	int i;
+	int buf_size;
+	int offset;
+	struct scsi_sense_hdr sshdr;
+#endif
+
 
 	switch (evt->evt_type) {
 	case SDEV_EVT_MEDIA_CHANGE:
@@ -2702,6 +2710,49 @@ static void scsi_evt_emit(struct scsi_device *sdev, struct scsi_event *evt)
 	case SDEV_EVT_ALUA_STATE_CHANGE_REPORTED:
 		envp[idx++] = "SDEV_UA=ASYMMETRIC_ACCESS_STATE_CHANGED";
 		break;
+#ifdef CONFIG_SCSI_SENSE_UEVENT
+	case SDEV_EVT_SCSI_SENSE:
+		/*
+		 * buf is used to store 3 strings: SENSE_CODE, CDB and
+		 * SENSE_BUFFER. 4 bytes are needed for each byte in cdb
+		 * and sense buffer. So the total size required is:
+		 *
+		 *   19 (SENSE_CODE=X/XX/XX\0) + 5 (CDB=\0) +
+		 *       14 (SENSE_BUFFER=\0) + 4 * (cdb_len + sb_len);
+		 */
+		buf_size = (evt->sense_evt_data.cmd_len +
+			    evt->sense_evt_data.sb_len) * 4 + 38;
+		buf = kzalloc(buf_size, GFP_KERNEL);
+		if (!buf)
+			break;
+		offset = 0;
+
+		envp[idx++] = "SDEV_SENSE=1";
+		envp[idx++] = buf;
+		scsi_normalize_sense(evt->sense_evt_data.sense_buffer,
+				     evt->sense_evt_data.sb_len, &sshdr);
+		offset += snprintf(buf + offset, buf_size - offset,
+				   "SENSE_CODE=%1x/%02x/%02x",
+				   sshdr.sense_key, sshdr.asc, sshdr.ascq);
+		offset++;
+
+		envp[idx++] = buf + offset;
+		offset += snprintf(buf + offset, buf_size - offset, "CDB=");
+		for (i = 0; i < evt->sense_evt_data.cmd_len; i++)
+			offset += snprintf(
+				buf + offset, buf_size - offset,
+				"\\x%02x", evt->sense_evt_data.cmnd[i]);
+
+		offset++;
+		envp[idx++] = buf + offset;
+		offset += snprintf(buf + offset, buf_size - offset,
+				   "SENSE_BUFFER=");
+		for (i = 0; i < evt->sense_evt_data.sb_len; i++)
+			offset += snprintf(
+				buf + offset, buf_size - offset,
+				"\\x%02x", evt->sense_evt_data.sense_buffer[i]);
+		break;
+#endif
 	default:
 		/* do nothing */
 		break;
@@ -2710,6 +2761,10 @@ static void scsi_evt_emit(struct scsi_device *sdev, struct scsi_event *evt)
 	envp[idx++] = NULL;
 
 	kobject_uevent_env(&sdev->sdev_gendev.kobj, KOBJ_CHANGE, envp);
+
+#ifdef CONFIG_SCSI_SENSE_UEVENT
+	kfree(buf);
+#endif
 }
 
 /**
@@ -2806,6 +2861,7 @@ struct scsi_event *sdev_evt_alloc(enum scsi_device_event evt_type,
 	case SDEV_EVT_MODE_PARAMETER_CHANGE_REPORTED:
 	case SDEV_EVT_LUN_CHANGE_REPORTED:
 	case SDEV_EVT_ALUA_STATE_CHANGE_REPORTED:
+	case SDEV_EVT_SCSI_SENSE:
 	default:
 		/* do nothing */
 		break;
diff --git a/drivers/scsi/scsi_sysfs.c b/drivers/scsi/scsi_sysfs.c
index d6984df..937609c 100644
--- a/drivers/scsi/scsi_sysfs.c
+++ b/drivers/scsi/scsi_sysfs.c
@@ -1074,6 +1074,54 @@ static DEVICE_ATTR(queue_ramp_up_period, S_IRUGO | S_IWUSR,
 		   sdev_show_queue_ramp_up_period,
 		   sdev_store_queue_ramp_up_period);
 
+#ifdef CONFIG_SCSI_SENSE_UEVENT
+
+/*
+ * SCSI sense key could be 0x00 - 0x0f,
+ */
+#define SCSI_SENSE_EVENT_FILTER_MASK	0xffff
+
+static ssize_t
+sdev_show_sense_event_filter(struct device *dev,
+			     struct device_attribute *attr,
+			     char *buf)
+{
+	struct scsi_device *sdev;
+
+	sdev = to_scsi_device(dev);
+	return snprintf(buf, 20, "0x%04lx\n",
+			(sdev->sense_event_filter &
+			 SCSI_SENSE_EVENT_FILTER_MASK));
+}
+
+static ssize_t
+sdev_store_sense_event_filter(struct device *dev,
+			      struct device_attribute *attr,
+			      const char *buf, size_t count)
+{
+	struct scsi_device *sdev = to_scsi_device(dev);
+	unsigned long filter;
+	int i;
+
+	if (kstrtoul(buf, 0, &filter))
+		return -EINVAL;
+
+	if ((filter & 0xffff) != filter)
+		return -EINVAL;
+
+	for (i = 0; i < 16; i++)
+		if (filter & SCSI_SENSE_EVENT_FILTER_MASK  & (1 << i))
+			set_bit(i, &sdev->sense_event_filter);
+		else
+			clear_bit(i, &sdev->sense_event_filter);
+	return count;
+}
+
+static DEVICE_ATTR(sense_event_filter, 0644,
+		   sdev_show_sense_event_filter,
+		   sdev_store_sense_event_filter);
+#endif
+
 static umode_t scsi_sdev_attr_is_visible(struct kobject *kobj,
 					 struct attribute *attr, int i)
 {
@@ -1144,6 +1192,9 @@ static struct attribute *scsi_sdev_attrs[] = {
 	&dev_attr_preferred_path.attr,
 #endif
 	&dev_attr_queue_ramp_up_period.attr,
+#ifdef CONFIG_SCSI_SENSE_UEVENT
+	&dev_attr_sense_event_filter.attr,
+#endif
 	REF_EVT(media_change),
 	REF_EVT(inquiry_change_reported),
 	REF_EVT(capacity_change_reported),
diff --git a/include/scsi/scsi_common.h b/include/scsi/scsi_common.h
index 20bf7ea..832ff62 100644
--- a/include/scsi/scsi_common.h
+++ b/include/scsi/scsi_common.h
@@ -24,6 +24,12 @@ scsi_command_size(const unsigned char *cmnd)
 		scsi_varlen_cdb_length(cmnd) : COMMAND_SIZE(cmnd[0]);
 }
 
+static inline unsigned char
+scsi_sense_data_length(const unsigned char *sense_buffer)
+{
+	return sense_buffer[7] + 8;
+}
+
 /* Returns a human-readable name for the device */
 extern const char *scsi_device_type(unsigned type);
 
diff --git a/include/scsi/scsi_device.h b/include/scsi/scsi_device.h
index b41ee9d..aa1ac28 100644
--- a/include/scsi/scsi_device.h
+++ b/include/scsi/scsi_device.h
@@ -64,13 +64,24 @@ enum scsi_device_event {
 	SDEV_EVT_MODE_PARAMETER_CHANGE_REPORTED,	/* 2A 01  UA reported */
 	SDEV_EVT_LUN_CHANGE_REPORTED,			/* 3F 0E  UA reported */
 	SDEV_EVT_ALUA_STATE_CHANGE_REPORTED,		/* 2A 06  UA reported */
+	SDEV_EVT_SCSI_SENSE,
 
 	SDEV_EVT_FIRST		= SDEV_EVT_MEDIA_CHANGE,
-	SDEV_EVT_LAST		= SDEV_EVT_ALUA_STATE_CHANGE_REPORTED,
+	SDEV_EVT_LAST		= SDEV_EVT_SCSI_SENSE,
 
 	SDEV_EVT_MAXBITS	= SDEV_EVT_LAST + 1
 };
 
+#ifdef CONFIG_SCSI_SENSE_UEVENT
+/* data for for SDEV_EVT_SCSI_SENSE */
+struct scsi_sense_uevent_data {
+	unsigned char		cmd_len;
+	unsigned char		*cmnd;
+	unsigned char		sb_len;
+	unsigned char		*sense_buffer;
+};
+#endif
+
 struct scsi_event {
 	enum scsi_device_event	evt_type;
 	struct list_head	node;
@@ -78,6 +89,11 @@ struct scsi_event {
 	/* put union of data structures, for non-simple event types,
 	 * here
 	 */
+	union {
+#ifdef CONFIG_SCSI_SENSE_UEVENT
+		struct scsi_sense_uevent_data sense_evt_data;
+#endif
+	};
 };
 
 struct scsi_device {
@@ -196,6 +212,15 @@ struct scsi_device {
 	atomic_t iodone_cnt;
 	atomic_t ioerr_cnt;
 
+#ifdef CONFIG_SCSI_SENSE_UEVENT
+	/*
+	 * filter of sense code uevent
+	 * setting bit X (0x00 - 0x0e) of sense_event_filter enables
+	 * uevent for sense key X
+	 */
+	unsigned long		sense_event_filter;
+#endif
+
 	struct device		sdev_gendev,
 				sdev_dev;
 
-- 
2.9.3

[RFC v3 2/2] scsi: add rate limit to scsi sense code uevent

[Song Liu]

This patch adds rate limits to SCSI sense code uevets. Currently,
the rate limit is hard-coded to 64 events per second per Scsi_Host.

The code tracks nano second time of latest 64 events in a circular
buffer. When a new event arrives, the time is compared against the
latest time in the buffer. If the difference is smaller than one
second, the new event is dropped.

Signed-off-by: Song Liu <songliubraving@fb.com>
---
 drivers/scsi/hosts.c      |  4 ++++
 drivers/scsi/scsi_error.c | 16 ++++++++++++++++
 include/scsi/scsi_host.h  | 13 +++++++++++++
 3 files changed, 33 insertions(+)

diff --git a/drivers/scsi/hosts.c b/drivers/scsi/hosts.c
index 831a1c8..219481b 100644
--- a/drivers/scsi/hosts.c
+++ b/drivers/scsi/hosts.c
@@ -408,6 +408,10 @@ struct Scsi_Host *scsi_host_alloc(struct scsi_host_template *sht, int privsize)
 	init_waitqueue_head(&shost->host_wait);
 	mutex_init(&shost->scan_mutex);
 
+#ifdef CONFIG_SCSI_SENSE_UEVENT
+	spin_lock_init(&shost->latest_event_lock);
+#endif
+
 	index = ida_simple_get(&host_index_ida, 0, 0, GFP_KERNEL);
 	if (index < 0)
 		goto fail_kfree;
diff --git a/drivers/scsi/scsi_error.c b/drivers/scsi/scsi_error.c
index b8ef869..a0f5aab 100644
--- a/drivers/scsi/scsi_error.c
+++ b/drivers/scsi/scsi_error.c
@@ -436,10 +436,26 @@ static void scsi_send_sense_uevent(struct scsi_device *sdev,
 #ifdef CONFIG_SCSI_SENSE_UEVENT
 	struct scsi_event *evt;
 	unsigned char sb_len;
+	struct Scsi_Host *shost = sdev->host;
+	unsigned long flags;
+	u64 time_ns;
 
 	if (!test_bit(sshdr->sense_key & 0xf,
 		      &sdev->sense_event_filter))
 		return;
+
+	time_ns = ktime_to_ns(ktime_get());
+	spin_lock_irqsave(&shost->latest_event_lock, flags);
+	if (time_ns - shost->latest_event_times[shost->latest_event_idx] <
+	    NSEC_PER_SEC) {
+		spin_unlock_irqrestore(&shost->latest_event_lock, flags);
+		return;
+	}
+	shost->latest_event_times[shost->latest_event_idx] = time_ns;
+	shost->latest_event_idx = (shost->latest_event_idx + 1) %
+		MAX_SENSE_EVENT_PER_SECOND;
+	spin_unlock_irqrestore(&shost->latest_event_lock, flags);
+
 	evt = sdev_evt_alloc(SDEV_EVT_SCSI_SENSE, GFP_ATOMIC);
 	if (!evt)
 		return;
diff --git a/include/scsi/scsi_host.h b/include/scsi/scsi_host.h
index afb0481..8aacb15 100644
--- a/include/scsi/scsi_host.h
+++ b/include/scsi/scsi_host.h
@@ -731,6 +731,19 @@ struct Scsi_Host {
 	 */
 	struct device *dma_dev;
 
+#ifdef CONFIG_SCSI_SENSE_UEVENT
+#define MAX_SENSE_EVENT_PER_SECOND	64
+	/*
+	 * To rate limit uevents to MAX_SENSE_EVENT_PER_SECOND, we track
+	 * nano second time of MAX_SENSE_EVENT_PER_SECOND most recent
+	 * events. If there are already MAX_SENSE_EVENT_PER_SECOND in the
+	 * past seconds, new event is dropped.
+	 */
+	u64		latest_event_times[MAX_SENSE_EVENT_PER_SECOND];
+	int		latest_event_idx;
+	spinlock_t	latest_event_lock;
+#endif
+
 	/*
 	 * We should ensure that this is aligned, both for better performance
 	 * and also because some compilers (m68k) don't automatically force
-- 
2.9.3

Re: [RFC v3 1/2] scsi: generate uevent for SCSI sense code

[Johannes Thumshirn]

On Wed, Jul 12, 2017 at 03:35:34PM -0700, Song Liu wrote:
> +	if (!test_bit(sshdr->sense_key & 0xf,
> +		      &sdev->sense_event_filter))

While being technically correct, this looks a bit kludgy. Please pass
in the whole sense_key without masking it.

Byte,
	Johannes
-- 
Johannes Thumshirn                                          Storage
jthumshirn@suse.de                                +49 911 74053 689
SUSE LINUX GmbH, Maxfeldstr. 5, 90409 Nürnberg
GF: Felix Imendörffer, Jane Smithard, Graham Norton
HRB 21284 (AG Nürnberg)
Key fingerprint = EC38 9CAB C2C4 F25D 8600 D0D0 0393 969D 2D76 0850