`nvme/039 => nvme1n1 (test error logging)` failed

[igaw]

figure out what's happening here:

https://github.com/linux-nvme/nvme-cli/actions/runs/21234453806/job/61099390574#step:3:2310

nvme/039 => nvme1n1 (test error logging)                     [failed]
    runtime    ...  5.688s
    --- tests/nvme/039.out	2026-01-22 03:11:43.373446123 +0000
    +++ /home/fedora/blktests/results/nvme1n1/nvme/039.out.bad	2026-01-22 03:26:26.693654215 +0000
    @@ -2,6 +2,6 @@
      Read(0x2) @ LBA 0, 1 blocks, Unrecovered Read Error (sct 0x2 / sc 0x81) DNR 
      Read(0x2) @ LBA 0, 1 blocks, Unknown (sct 0x3 / sc 0x75) DNR 
      Write(0x1) @ LBA 0, 1 blocks, Write Fault (sct 0x2 / sc 0x80) DNR 
    - Identify(0x6), Access Denied (sct 0x2 / sc 0x86) DNR cdw10=0x1 cdw11=0x0 cdw12=0x0 cdw13=0x0 cdw14=0x0 cdw15=0x0
    + Identify(0x0), Access Denied (sct 0x2 / sc 0x86) DNR cdw10=0x0 cdw11=0x0 cdw12=0x0 cdw13=0x0 cdw14=0x0 cdw15=0x0
      Read(0x2), Invalid Command Opcode (sct 0x0 / sc 0x1) DNR cdw10=0x0 cdw11=0x0 cdw12=0x1 cdw13=0x0 cdw14=0x0 cdw15=0x0
     Test complete

[igaw]

nvme/039 fails in

inject_access_denied_on_identify()
{
	# Inject a 'Access Denied' (0x286) status error on an
	# Identify admin command
	_nvme_enable_err_inject "$1" 0 100 1 0x286 1

	nvme admin-passthru /dev/"$1" --opcode=0x06 --data-len=4096 \
	    --cdw10=1 -r 2> /dev/null 1>&2

	_nvme_disable_err_inject "$1"

	if ${nvme_verbose_errors}; then
		last_dmesg 1 | grep "Access Denied (" | \
		    sed 's/nvme.*://g'
	else
		last_dmesg 1 | grep "Admin Cmd(" | \
		    sed 's/Admin Cmd/Identify/g' | \
		    sed 's/I\/O Error/Access Denied/g' | \
		    sed 's/nvme.*://g'
	fi
}

The nvme admin-passthru command submits following command:

root@localhost:~# nvme admin-passthru /dev/nvme0n1 --opcode=0x06 --data-len=4096 --cdw10=1 -r -d
opcode       : 06
flags        : 00
rsvd1        : 0000
nsid         : 00000000
cdw2         : 00000000
cdw3         : 00000000
data_len     : 00001000
metadata_len : 00000000
addr         : 55b3660ba000
metadata     : 0
cdw10        : 00000001
cdw11        : 00000000
cdw12        : 00000000
cdw13        : 00000000
cdw14        : 00000000
cdw15        : 00000000
timeout_ms   : 00000000

This looks all good (identically with an output from nvme-cli v2.11).

My test VM shows slightly different output though (6.19.0-rc6)

[  500.632862] run blktests nvme/039 at 2026-01-23 08:29:09
[  505.811298] nvme0n1: Read(0x2) @ LBA 0, 1 blocks, Unrecovered Read Error (sct 0x2 / sc 0x81) DNR
[  505.811746] critical medium error, dev nvme0n1, sector 0 op 0x0:(READ) flags 0x800 phys_seg 1 prio class 2
[  505.939208] nvme0n1: Read(0x2) @ LBA 0, 1 blocks, Unknown (sct 0x3 / sc 0x75) DNR
[  505.939616] I/O error, dev nvme0n1, sector 0 op 0x0:(READ) flags 0x800 phys_seg 1 prio class 2
[  506.065759] nvme0n1: Write(0x1) @ LBA 0, 1 blocks, Write Fault (sct 0x2 / sc 0x80) DNR
[  506.066172] critical medium error, dev nvme0n1, sector 0 op 0x1:(WRITE) flags 0x8800 phys_seg 1 prio class 2
[  506.381524] nvme0: Delete SQ(0x0), Access Denied (sct 0x2 / sc 0x86) DNR cdw10=0x0 cdw11=0x0 cdw12=0x0 cdw13=0x0 cdw14=0x0 cdw15=0x0
[  506.540014] nvme0: Delete SQ(0x0), Invalid Queue Identifier (sct 0x1 / sc 0x1) DNR cdw10=0x0 cdw11=0x0 cdw12=0x0 cdw13=0x0 cdw14=0x0 cdw15=0x0
[  506.695121] nvme0: Delete SQ(0x0), Invalid Queue Identifier (sct 0x1 / sc 0x1) DNR cdw10=0x0 cdw11=0x0 cdw12=0x0 cdw13=0x0 cdw14=0x0 cdw15=0x0
[  506.695821] nvme0n1: Read(0x2), Invalid Command Opcode (sct 0x0 / sc 0x1) DNR cdw10=0x0 cdw11=0x0 cdw12=0x1 cdw13=0x0 cdw14=0x0 cdw15=0x0

This might a different problem on my system.

[igaw]

• nvme-cli master and Linux v6.18: fails
• nvme-cli v2.16 and Linux v6.18: passes

[igaw]

Found the problem. So nvme-cli 3.x is probing if it is possible to use the admin64 interface.

static int __nvme_transport_handle_open_direct(struct nvme_transport_handle *hdl, const char *devname)
{
	[...]

	ret = ioctl(hdl->fd, NVME_IOCTL_ADMIN64_CMD, &dummy);
	if (ret > 0)
		hdl->ioctl64 = true;

When I remove this tests, the tests passes and it all make sense. dummy is all zeroed out, thus the failed command reported is this tests not the identify.

I think the test assumes too much about how things work. If there is any other process isssue command it randomly shoots down an unrelated command. WDYT? @kawasaki

[ikegami-t]

The function: __nvme_transport_handle_open_direct() always returns only the negative or zero values and not returns the positive value but does this really cause the following test failure? (Also if the dummy command failed then the opcode: 00h is the delete i/O submission queue but not the identify command as the test result output.)

    + Identify(0x0), Access Denied (sct 0x2 / sc 0x86) DNR cdw10=0x0 cdw11=0x0 cdw12=0x0 cdw13=0x0 cdw14=0x0 cdw15=0x0

[igaw]

The test is failing because it assumes the first ioctl is the expected IO command but in this case it's the admin command.

[ikegami-t]

Seems the output failed printed by the kernel code below but the output Identify(0x0) used nr->cmd->common.opcode for both then strange since Identify (nvme_get_opcode_str(nr->cmd->common.opcode) or nvme_get_admin_opcode_str(nr->cmd->common.opcode)) and 0x0 (nr->cmd->common.opcode).
<drivers/nvme/host/core.c>

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),
		NVME_SCT(nr->status),		/* Status Code Type */
		nr->status & NVME_SC_MASK,	/* Status Code */
		nr->status & NVME_STATUS_MORE ? "MORE " : "",
		nr->status & NVME_STATUS_DNR  ? "DNR "  : "",
		le32_to_cpu(nr->cmd->common.cdw10),
		le32_to_cpu(nr->cmd->common.cdw11),
		le32_to_cpu(nr->cmd->common.cdw12),
		le32_to_cpu(nr->cmd->common.cdw13),
		le32_to_cpu(nr->cmd->common.cdw14),
		le32_to_cpu(nr->cmd->common.cdw15));
}

[igaw]

We can close this one now. It is fixed with ##3094 and #linux-blktests/blktests#227