[PATCH V6 0/1] nvme: allow passthru cmd error logging

[PATCH V6 0/1] nvme: allow passthru cmd error logging

[Chaitanya Kulkarni]

Hi,

In nvme_end_req() we only log errors which are for non-passthru
commands. Add a helper function nvme_log_err_passthru() that allows us
to log error for passthru commands by decoding cdw10-cdw15 values of
nvme command.

Below is short testlog :-

* Admin Passsthru error log off, no errors are printed
* Admin Passsthru error log on, errors are printed
* IO Passsthru error log off, errors are printed
* IO Passsthru error log on, errors are printed

-ck

Chaitanya Kulkarni (1):
  nvme: allow passthru cmd error logging

v6:
- Reabse, etest nvme-6.5 and add test log for admin and I/O
  passthru error log.

v5:
- Trim down code in the nvme_log_error_passthrough().
  Use following to get the disk name as an arg to
   pr_err_ratelimited() :-
	ns ? ns->disk->disk_name : dev_name(nr->ctrl->device),
  Use following to get the admin vs I/O opcode string as an arg to
  pr_err_ratelimited() :-
       	ns ? nvme_get_opcode_str(nr->cmd->common.opcode) :
       	     nvme_get_admin_opcode_str(nr->cmd->common.opcode),
- Rename nvme_log_error_passthrough() -> nvme_log_err_passthru().
- Remove else and return directly in nvme_passthru_err_log_show().
- Generate error on invalid values of the passthru_enable variable
  in nvme_passthru_log_store().
- Rename passthrough -> passthru.
- Rename sysfs attr from passthru_admin_err_logging -> passthru_log_err.

v4:
- Change sysfs attribute to passthru_admin_err_logging
- Only log passthrough admin commands.  IO passthrough commands will
  always be logged.

v3:
- Log a passthrough specific message that dumps CDW* contents.
- Enable/disable vis sysfs rather than debugfs.

v2:
- Included Pankaj Raghav's patch 'nvme: ignore starting sector while 
  error logging for passthrough requests'
  with a couple changes.
- Moved error_logging flag to nvme_ctrl structure
- The entire nvme-debugfs.c does not need to be guarded by 
  #ifdef CONFIG_FAULT_INJECTION_DEBUG_FS.
- Use IS_ENABLED((CONFIG_NVME_ERROR_LOGGING_DEBUG_FS)) to determine if 
  error logging should be initialized.
- Various other nits.

 drivers/nvme/host/core.c  | 43 ++++++++++++++++++++++++++++++++++-----
 drivers/nvme/host/nvme.h  |  1 +
 drivers/nvme/host/sysfs.c | 39 +++++++++++++++++++++++++++++++++++
 3 files changed, 78 insertions(+), 5 deletions(-)

* Admin Passsthru error log off, no errors are printed :-

nvme (nvme-6.5) #
nvme (nvme-6.5) # echo 0 > /sys/class/nvme/nvme0/passthru_err_log
nvme (nvme-6.5) # nvme telemetry-log -o /tmp/test /dev/nvme0
NVMe status: Invalid Field in Command: A reserved coded value or an unsupported value in a defined field(0x4002)
Failed to acquire telemetry log 16386!
nvme (nvme-6.5) # cd -
/sys/kernel/debug/tracing/events/nvme
nvme # cd -
/mnt/data/nvme
nvme (nvme-6.5) # dmesg  -c

* Admin Passsthru error log on, errors are printed :-

nvme (nvme-6.5) # echo 1 > /sys/class/nvme/nvme0/passthru_err_log
nvme (nvme-6.5) # nvme telemetry-log -o /tmp/test /dev/nvme0
NVMe status: Invalid Field in Command: A reserved coded value or an unsupported value in a defined field(0x4002)
Failed to acquire telemetry log 16386!
nvme (nvme-6.5) # dmesg  -c
[  860.013105] nvme0: Get Log Page(0x2), Invalid Field in Command (sct 0x0 / sc 0x2) DNR cdw10=0x7f0107 cdw11=0x0 cdw12=0x0 cdw13=0x0 cdw14=0x0 cdw15=0x0
nvme (nvme-6.5) #
nvme (nvme-6.5) #

* IO Passsthru error log off, errors are printed :-

nvme (nvme-6.5) #  echo 0 > /sys/class/nvme/nvme0/passthru_err_log
nvme (nvme-6.5) # nvme write-zeroes -n 1 -s 0x200000 -c 10 /dev/nvme0
NVMe status: LBA Out of Range: The command references an LBA that exceeds the size of the namespace(0x4080)
nvme (nvme-6.5) # dmesg -c
[73675.769162] nvme nvme0: using deprecated NVME_IOCTL_IO_CMD ioctl on the char device!
[73675.769233] nvme0n1: Write Zeroes(0x8), LBA Out of Range (sct 0x0 / sc 0x80) DNR cdw10=0x200000 cdw11=0x0 cdw12=0xa cdw13=0x0 cdw14=0x0 cdw15=0x0

* IO Passsthru error log on, errors are printed :-

nvme (nvme-6.5) #  echo 1 > /sys/class/nvme/nvme0/passthru_err_log
nvme (nvme-6.5) # nvme write-zeroes -n 1 -s 0x200000 -c 10 /dev/nvme0
NVMe status: LBA Out of Range: The command references an LBA that exceeds the size of the namespace(0x4080)
nvme (nvme-6.5) # dmesg -c
[73684.208241] nvme nvme0: using deprecated NVME_IOCTL_IO_CMD ioctl on the char device!
[73684.208419] nvme0n1: Write Zeroes(0x8), LBA Out of Range (sct 0x0 / sc 0x80) DNR cdw10=0x200000 cdw11=0x0 cdw12=0xa cdw13=0x0 cdw14=0x0 cdw15=0x0
nvme (nvme-6.5) # 

-- 
2.40.0

[PATCH V6 1/1] nvme: allow passthru cmd error logging

[Chaitanya Kulkarni]

From: Alan Adamson <alan.adamson@oracle.com>

Commit d7ac8dca938c ("nvme: quiet user passthrough command errors")
disabled error logging for user passthrough commands.  This commit
adds the ability to opt-in to passthrough admin error logging. IO
commands initiated as passthrough will always be logged.

The logging output for passthrough commands (Admin and IO) has been
changed to include CDWXX fields.

nvme0n1: Read(0x2), LBA Out of Range (sct 0x0 / sc 0x80) DNR cdw10=0x0 cdw11=0x1
        cdw12=0x70000 cdw13=0x0 cdw14=0x0 cdw15=0x0

Add a helper function nvme_log_err_passthru() which allows us to log
error for passthru commands by decoding cdw10-cdw15 values of nvme
command.

Add a new sysfs attr passthru_err_log that allows user to conditionally
enable passthru command logging, by default it is disabled.

To enable passthrough admin error logging:
        echo 1 > /sys/class/nvme/nvme0/passthru_err_log

To disable passthrough admin error logging:
        echo 0 > /sys/class/nvme/nvme0/passthru_err_log

Signed-off-by: Alan Adamson <alan.adamson@oracle.com>
[kch] fix sevaral nits and trim down code, details in cover-letter.
Signed-off-by: Chaitanya Kulkarni <kch@nvidia.com>
---
 drivers/nvme/host/core.c  | 43 ++++++++++++++++++++++++++++++++++-----
 drivers/nvme/host/nvme.h  |  1 +
 drivers/nvme/host/sysfs.c | 39 +++++++++++++++++++++++++++++++++++
 3 files changed, 78 insertions(+), 5 deletions(-)

diff --git a/drivers/nvme/host/core.c b/drivers/nvme/host/core.c
index 4b7f9edab5e8..62cb9d011b89 100644
--- a/drivers/nvme/host/core.c
+++ b/drivers/nvme/host/core.c
@@ -337,6 +337,30 @@ static void nvme_log_error(struct request *req)
 			   nr->status & NVME_SC_DNR  ? "DNR "  : "");
 }
 
+static void nvme_log_err_passthru(struct request *req)
+{
+	struct nvme_ns *ns = req->q->queuedata;
+	struct nvme_request *nr = nvme_req(req);
+
+	pr_err_ratelimited("%s: %s(0x%x), %s (sct 0x%x / sc 0x%x) %s%s"
+		"cdw10=0x%x cdw11=0x%x cdw12=0x%x cdw13=0x%x cdw14=0x%x cdw15=0x%x\n",
+		ns ? ns->disk->disk_name : dev_name(nr->ctrl->device),
+		ns ? nvme_get_opcode_str(nr->cmd->common.opcode) :
+		     nvme_get_admin_opcode_str(nr->cmd->common.opcode),
+		nr->cmd->common.opcode,
+		nvme_get_error_status_str(nr->status),
+		nr->status >> 8 & 7,	/* Status Code Type */
+		nr->status & 0xff,	/* Status Code */
+		nr->status & NVME_SC_MORE ? "MORE " : "",
+		nr->status & NVME_SC_DNR  ? "DNR "  : "",
+		nr->cmd->common.cdw10,
+		nr->cmd->common.cdw11,
+		nr->cmd->common.cdw12,
+		nr->cmd->common.cdw13,
+		nr->cmd->common.cdw14,
+		nr->cmd->common.cdw14);
+}
+
 enum nvme_disposition {
 	COMPLETE,
 	RETRY,
@@ -381,8 +405,12 @@ static inline void nvme_end_req(struct request *req)
 {
 	blk_status_t status = nvme_error_status(nvme_req(req)->status);
 
-	if (unlikely(nvme_req(req)->status && !(req->rq_flags & RQF_QUIET)))
-		nvme_log_error(req);
+	if (unlikely(nvme_req(req)->status && !(req->rq_flags & RQF_QUIET))) {
+		if (blk_rq_is_passthrough(req))
+			nvme_log_err_passthru(req);
+		else
+			nvme_log_error(req);
+	}
 	nvme_end_req_zoned(req);
 	nvme_trace_bio_complete(req);
 	if (req->cmd_flags & REQ_NVME_MPATH)
@@ -666,10 +694,15 @@ static inline void nvme_clear_nvme_request(struct request *req)
 /* initialize a passthrough request */
 void nvme_init_request(struct request *req, struct nvme_command *cmd)
 {
+	struct nvme_request *nr = nvme_req(req);
+
 	if (req->q->queuedata)
 		req->timeout = NVME_IO_TIMEOUT;
-	else /* no queuedata implies admin queue */
+	else { /* no queuedata implies admin queue */
 		req->timeout = NVME_ADMIN_TIMEOUT;
+		if (!nr->ctrl->passthru_log_err)
+			req->rq_flags |= RQF_QUIET;
+	}
 
 	/* passthru commands should let the driver set the SGL flags */
 	cmd->common.flags &= ~NVME_CMD_SGL_ALL;
@@ -678,8 +711,7 @@ void nvme_init_request(struct request *req, struct nvme_command *cmd)
 	if (req->mq_hctx->type == HCTX_TYPE_POLL)
 		req->cmd_flags |= REQ_POLLED;
 	nvme_clear_nvme_request(req);
-	req->rq_flags |= RQF_QUIET;
-	memcpy(nvme_req(req)->cmd, cmd, sizeof(*cmd));
+	memcpy(nr->cmd, cmd, sizeof(*cmd));
 }
 EXPORT_SYMBOL_GPL(nvme_init_request);
 
@@ -4483,6 +4515,7 @@ int nvme_init_ctrl(struct nvme_ctrl *ctrl, struct device *dev,
 	int ret;
 
 	ctrl->state = NVME_CTRL_NEW;
+	ctrl->passthru_log_err = false;
 	clear_bit(NVME_CTRL_FAILFAST_EXPIRED, &ctrl->flags);
 	spin_lock_init(&ctrl->lock);
 	mutex_init(&ctrl->scan_lock);
diff --git a/drivers/nvme/host/nvme.h b/drivers/nvme/host/nvme.h
index f3182134487a..fe305d4a9f1b 100644
--- a/drivers/nvme/host/nvme.h
+++ b/drivers/nvme/host/nvme.h
@@ -249,6 +249,7 @@ enum nvme_ctrl_flags {
 struct nvme_ctrl {
 	bool comp_seen;
 	bool identified;
+	bool passthru_log_err;
 	enum nvme_ctrl_state state;
 	spinlock_t lock;
 	struct mutex scan_lock;
diff --git a/drivers/nvme/host/sysfs.c b/drivers/nvme/host/sysfs.c
index 45e91811f905..2dca06378998 100644
--- a/drivers/nvme/host/sysfs.c
+++ b/drivers/nvme/host/sysfs.c
@@ -35,6 +35,44 @@ static ssize_t nvme_sysfs_rescan(struct device *dev,
 }
 static DEVICE_ATTR(rescan_controller, S_IWUSR, NULL, nvme_sysfs_rescan);
 
+static ssize_t nvme_passthru_err_log_show(struct device *dev,
+		struct device_attribute *attr, char *buf)
+{
+	struct nvme_ctrl *ctrl = dev_get_drvdata(dev);
+
+	if (ctrl->passthru_log_err)
+		return sysfs_emit(buf, "on\n");
+
+	return sysfs_emit(buf, "off\n");
+}
+
+static ssize_t nvme_passthru_err_log_store(struct device *dev,
+		struct device_attribute *attr, const char *buf, size_t count)
+{
+	struct nvme_ctrl *ctrl = dev_get_drvdata(dev);
+	int passthru_enable, err;
+
+	err = kstrtoint(buf, 10, &passthru_enable);
+	if (err)
+		return -EINVAL;
+
+	switch (passthru_enable) {
+	case true:
+	case false:
+		ctrl->passthru_log_err = passthru_enable;
+		break;
+	default:
+		pr_err("invlid value %d for admin error logging [on:1 off:0]\n",
+			passthru_enable);
+		break;
+	}
+	return count;
+}
+
+static DEVICE_ATTR(passthru_err_log, S_IRUGO | S_IWUSR,
+	nvme_passthru_err_log_show,
+	nvme_passthru_err_log_store);
+
 static inline struct nvme_ns_head *dev_to_ns_head(struct device *dev)
 {
 	struct gendisk *disk = dev_to_disk(dev);
@@ -554,6 +592,7 @@ static struct attribute *nvme_dev_attrs[] = {
 	&dev_attr_dhchap_secret.attr,
 	&dev_attr_dhchap_ctrl_secret.attr,
 #endif
+	&dev_attr_passthru_err_log.attr,
 	NULL
 };
 
-- 
2.40.0

Re: [PATCH V6 1/1] nvme: allow passthru cmd error logging

[Christoph Hellwig]

> +
> +	if (ctrl->passthru_log_err)
> +		return sysfs_emit(buf, "on\n");
> +
> +	return sysfs_emit(buf, "off\n");

	return  sysfs_emit(buf, ctrl->passthru_log_err ? "on" : "off");

> +}
> +
> +static ssize_t nvme_passthru_err_log_store(struct device *dev,
> +		struct device_attribute *attr, const char *buf, size_t count)
> +{
> +	struct nvme_ctrl *ctrl = dev_get_drvdata(dev);
> +	int passthru_enable, err;
> +
> +	err = kstrtoint(buf, 10, &passthru_enable);
> +	if (err)
> +		return -EINVAL;
> +
> +	switch (passthru_enable) {
> +	case true:
> +	case false:
> +		ctrl->passthru_log_err = passthru_enable;
> +		break;
> +	default:
> +		pr_err("invlid value %d for admin error logging [on:1 off:0]\n",
> +			passthru_enable);
> +		break;
> +	}
> +	return count;

This should use kstrtobool.

Also I thik the flag feels a bit too sparse.  Why not
something like passthru_err_log_enabled that explains what it does?

Re: [PATCH V6 1/1] nvme: allow passthru cmd error logging

[Chaitanya Kulkarni]

On 8/2/2023 5:01 AM, Christoph Hellwig wrote:
>> +
>> +	if (ctrl->passthru_log_err)
>> +		return sysfs_emit(buf, "on\n");
>> +
>> +	return sysfs_emit(buf, "off\n");
> 
> 	return  sysfs_emit(buf, ctrl->passthru_log_err ? "on" : "off");

okay..

> 
>> +}
>> +
>> +static ssize_t nvme_passthru_err_log_store(struct device *dev,
>> +		struct device_attribute *attr, const char *buf, size_t count)
>> +{
>> +	struct nvme_ctrl *ctrl = dev_get_drvdata(dev);
>> +	int passthru_enable, err;
>> +
>> +	err = kstrtoint(buf, 10, &passthru_enable);
>> +	if (err)
>> +		return -EINVAL;
>> +
>> +	switch (passthru_enable) {
>> +	case true:
>> +	case false:
>> +		ctrl->passthru_log_err = passthru_enable;
>> +		break;
>> +	default:
>> +		pr_err("invlid value %d for admin error logging [on:1 off:0]\n",
>> +			passthru_enable);
>> +		break;
>> +	}
>> +	return count;
> 
> This should use kstrtobool.

indeed, forget to change it to bool will add to next version ..

> 
> Also I thik the flag feels a bit too sparse.  Why not
> something like passthru_err_log_enabled that explains what it does?

sure, I'll send V7 with above changes ..

-ck

Re: [PATCH V6 0/1] nvme: allow passthru cmd error logging

[Chaitanya Kulkarni]

On 6/28/23 18:17, Chaitanya Kulkarni wrote:
> Hi,
>
> In nvme_end_req() we only log errors which are for non-passthru
> commands. Add a helper function nvme_log_err_passthru() that allows us
> to log error for passthru commands by decoding cdw10-cdw15 values of
> nvme command.
>
> Below is short testlog :-
>
> * Admin Passsthru error log off, no errors are printed
> * Admin Passsthru error log on, errors are printed
> * IO Passsthru error log off, errors are printed
> * IO Passsthru error log on, errors are printed
>
> -ck

Sagi, Christoph, Keith,

Can you guys please have a look into this ?

-ck

> Chaitanya Kulkarni (1):
>    nvme: allow passthru cmd error logging
>
> v6:
> - Reabse, etest nvme-6.5 and add test log for admin and I/O
>    passthru error log.
>
> v5:
> - Trim down code in the nvme_log_error_passthrough().
>    Use following to get the disk name as an arg to
>     pr_err_ratelimited() :-
> 	ns ? ns->disk->disk_name : dev_name(nr->ctrl->device),
>    Use following to get the admin vs I/O opcode string as an arg to
>    pr_err_ratelimited() :-
>         	ns ? nvme_get_opcode_str(nr->cmd->common.opcode) :
>         	     nvme_get_admin_opcode_str(nr->cmd->common.opcode),
> - Rename nvme_log_error_passthrough() -> nvme_log_err_passthru().
> - Remove else and return directly in nvme_passthru_err_log_show().
> - Generate error on invalid values of the passthru_enable variable
>    in nvme_passthru_log_store().
> - Rename passthrough -> passthru.
> - Rename sysfs attr from passthru_admin_err_logging -> passthru_log_err.
>
> v4:
> - Change sysfs attribute to passthru_admin_err_logging
> - Only log passthrough admin commands.  IO passthrough commands will
>    always be logged.
>
> v3:
> - Log a passthrough specific message that dumps CDW* contents.
> - Enable/disable vis sysfs rather than debugfs.
>
> v2:
> - Included Pankaj Raghav's patch 'nvme: ignore starting sector while
>    error logging for passthrough requests'
>    with a couple changes.
> - Moved error_logging flag to nvme_ctrl structure
> - The entire nvme-debugfs.c does not need to be guarded by
>    #ifdef CONFIG_FAULT_INJECTION_DEBUG_FS.
> - Use IS_ENABLED((CONFIG_NVME_ERROR_LOGGING_DEBUG_FS)) to determine if
>    error logging should be initialized.
> - Various other nits.
>
>   drivers/nvme/host/core.c  | 43 ++++++++++++++++++++++++++++++++++-----
>   drivers/nvme/host/nvme.h  |  1 +
>   drivers/nvme/host/sysfs.c | 39 +++++++++++++++++++++++++++++++++++
>   3 files changed, 78 insertions(+), 5 deletions(-)
>
> * Admin Passsthru error log off, no errors are printed :-
>
> nvme (nvme-6.5) #
> nvme (nvme-6.5) # echo 0 > /sys/class/nvme/nvme0/passthru_err_log
> nvme (nvme-6.5) # nvme telemetry-log -o /tmp/test /dev/nvme0
> NVMe status: Invalid Field in Command: A reserved coded value or an unsupported value in a defined field(0x4002)
> Failed to acquire telemetry log 16386!
> nvme (nvme-6.5) # cd -
> /sys/kernel/debug/tracing/events/nvme
> nvme # cd -
> /mnt/data/nvme
> nvme (nvme-6.5) # dmesg  -c
>
> * Admin Passsthru error log on, errors are printed :-
>
> nvme (nvme-6.5) # echo 1 > /sys/class/nvme/nvme0/passthru_err_log
> nvme (nvme-6.5) # nvme telemetry-log -o /tmp/test /dev/nvme0
> NVMe status: Invalid Field in Command: A reserved coded value or an unsupported value in a defined field(0x4002)
> Failed to acquire telemetry log 16386!
> nvme (nvme-6.5) # dmesg  -c
> [  860.013105] nvme0: Get Log Page(0x2), Invalid Field in Command (sct 0x0 / sc 0x2) DNR cdw10=0x7f0107 cdw11=0x0 cdw12=0x0 cdw13=0x0 cdw14=0x0 cdw15=0x0
> nvme (nvme-6.5) #
> nvme (nvme-6.5) #
>
> * IO Passsthru error log off, errors are printed :-
>
> nvme (nvme-6.5) #  echo 0 > /sys/class/nvme/nvme0/passthru_err_log
> nvme (nvme-6.5) # nvme write-zeroes -n 1 -s 0x200000 -c 10 /dev/nvme0
> NVMe status: LBA Out of Range: The command references an LBA that exceeds the size of the namespace(0x4080)
> nvme (nvme-6.5) # dmesg -c
> [73675.769162] nvme nvme0: using deprecated NVME_IOCTL_IO_CMD ioctl on the char device!
> [73675.769233] nvme0n1: Write Zeroes(0x8), LBA Out of Range (sct 0x0 / sc 0x80) DNR cdw10=0x200000 cdw11=0x0 cdw12=0xa cdw13=0x0 cdw14=0x0 cdw15=0x0
>
> * IO Passsthru error log on, errors are printed :-
>
> nvme (nvme-6.5) #  echo 1 > /sys/class/nvme/nvme0/passthru_err_log
> nvme (nvme-6.5) # nvme write-zeroes -n 1 -s 0x200000 -c 10 /dev/nvme0
> NVMe status: LBA Out of Range: The command references an LBA that exceeds the size of the namespace(0x4080)
> nvme (nvme-6.5) # dmesg -c
> [73684.208241] nvme nvme0: using deprecated NVME_IOCTL_IO_CMD ioctl on the char device!
> [73684.208419] nvme0n1: Write Zeroes(0x8), LBA Out of Range (sct 0x0 / sc 0x80) DNR cdw10=0x200000 cdw11=0x0 cdw12=0xa cdw13=0x0 cdw14=0x0 cdw15=0x0
> nvme (nvme-6.5) #
>