blktests v3 tests/nvme: add tests for error logging

blktests v3 tests/nvme: add tests for error logging

[Alan Adamson]

blktests tests/nvme: add tests for error logging

Test nvme error logging by injecting errors. Kernel must have FAULT_INJECTION
and FAULT_INJECTION_DEBUG_FS configured to use error injector. Tests can be
run with or without NVME_VERBOSE_ERRORS configured.

These test verify the functionality delivered by the follow:
        commit bd83fe6f2cd2 ("nvme: add verbose error logging")

V2 - Update from suggestions from shinichiro.kawasaki@wdc.com
V3 - Add error injector helper functions to nvme/rc


Alan Adamson (2):
  tests/nvme: add helper routine to use error injector
  tests/nvme: add tests for error logging

 tests/nvme/039     | 152 +++++++++++++++++++++++++++++++++++++++++++++
 tests/nvme/039.out |   7 +++
 tests/nvme/rc      |  44 +++++++++++++
 3 files changed, 203 insertions(+)
 create mode 100755 tests/nvme/039
 create mode 100644 tests/nvme/039.out

-- 
2.27.0

[PATCH v3 blktests 1/2] tests/nvme: add helper routines to use error injector

[Alan Adamson]

nvme tests can use these helper routines to setup and use
the nvme error injector.

Signed-off-by: Alan Adamson <alan.adamson@oracle.com>
---
 tests/nvme/rc | 44 ++++++++++++++++++++++++++++++++++++++++++++
 1 file changed, 44 insertions(+)

diff --git a/tests/nvme/rc b/tests/nvme/rc
index 3c38408a0bfe..c49a3c5d78da 100644
--- a/tests/nvme/rc
+++ b/tests/nvme/rc
@@ -375,3 +375,47 @@ _discovery_genctr() {
 	_nvme_discover "${nvme_trtype}" |
 		sed -n -e 's/^.*Generation counter \([0-9]\+\).*$/\1/p'
 }
+
+declare -A NS_DEV_FAULT_INJECT_SAVE
+declare -A CTRL_DEV_FAULT_INJECT_SAVE
+
+_nvme_err_inject_setup()
+{
+        local a
+
+        for a in /sys/kernel/debug/"$1"/fault_inject/*; do
+                NS_DEV_FAULT_INJECT_SAVE[${a}]=$(<"${a}")
+        done
+
+        for a in /sys/kernel/debug/"$2"/fault_inject/*; do
+                CTRL_DEV_FAULT_INJECT_SAVE[${a}]=$(<"${a}")
+        done
+}
+
+_nvme_err_inject_cleanup()
+{
+        local a
+
+        for a in /sys/kernel/debug/"${ns_dev}"/fault_inject/*; do
+                echo "${NS_DEV_FAULT_INJECT_SAVE[${a}]}" > "${a}"
+		echo ${a} $(<"${a}") >> /tmp/iii
+        done
+        for a in /sys/kernel/debug/"${ctrl_dev}"/fault_inject/*; do
+                echo "${CTRL_DEV_FAULT_INJECT_SAVE[${a}]}" > "${a}"
+        done
+}
+
+_nvme_enable_err_inject()
+{
+        echo "$2" > /sys/kernel/debug/"$1"/fault_inject/verbose
+        echo "$3" > /sys/kernel/debug/"$1"/fault_inject/probability
+        echo "$4" > /sys/kernel/debug/"$1"/fault_inject/dont_retry
+        echo "$5" > /sys/kernel/debug/"$1"/fault_inject/status
+        echo "$6" > /sys/kernel/debug/"$1"/fault_inject/times
+}
+
+_nvme_clear_err_inject()
+{
+        echo 0 > /sys/kernel/debug/"$1"/fault_inject/probability
+        echo 0 > /sys/kernel/debug/"$1"/fault_inject/times
+}
-- 
2.27.0

[PATCH v3 blktests 2/2] tests/nvme: add tests for error logging

[Alan Adamson]

Test nvme error logging by injecting errors. Kernel must have FAULT_INJECTION
and FAULT_INJECTION_DEBUG_FS configured to use error injector. Tests can be
run with or without NVME_VERBOSE_ERRORS configured.

Signed-off-by: Alan Adamson <alan.adamson@oracle.com>
Signed-off-by: Chaitanya Kulkarni <kch@nvidia.com>
---
 tests/nvme/039     | 152 +++++++++++++++++++++++++++++++++++++++++++++
 tests/nvme/039.out |   7 +++
 2 files changed, 159 insertions(+)
 create mode 100755 tests/nvme/039
 create mode 100644 tests/nvme/039.out

diff --git a/tests/nvme/039 b/tests/nvme/039
new file mode 100755
index 000000000000..dd216cbb2ef0
--- /dev/null
+++ b/tests/nvme/039
@@ -0,0 +1,152 @@
+#!/bin/bash
+# SPDX-License-Identifier: GPL-3.0+
+# Copyright (C) 2022 Oracle and/or its affiliates
+#
+# Test nvme error logging by injecting errors. Kernel must have FAULT_INJECTION
+# and FAULT_INJECTION_DEBUG_FS configured to use error injector. Tests can be
+# run with or without NVME_VERBOSE_ERRORS configured.
+#
+# Test for commit bd83fe6f2cd2 ("nvme: add verbose error logging").
+
+. tests/nvme/rc
+DESCRIPTION="test error logging"
+QUICK=1
+
+requires() {
+	_nvme_requires
+	_have_kernel_option FAULT_INJECTION && \
+	    _have_kernel_option FAULT_INJECTION_DEBUG_FS
+}
+
+inject_unrec_read_read()
+{
+	# Inject a 'Unrecovered Read Error' (0x281) status error on a READ
+	_nvme_enable_err_inject "$1" 0 100 1 0x281 1
+
+	dd if=/dev/"$1" of=/dev/null bs=512 count=1 iflag=direct \
+	    2> /dev/null 1>&2
+
+	_nvme_clear_err_inject "$1"
+	if ${nvme_verbose_errors}; then
+		dmesg -t | tail -2 | grep "Unrecovered Read Error (" | \
+		    sed 's/nvme.*://g'
+	else
+		dmesg -t | tail -2 | grep "Cmd(" | sed 's/I\/O Cmd/Read/g' | \
+		    sed 's/I\/O Error/Unrecovered Read Error/g' | \
+		    sed 's/nvme.*://g'
+	fi
+}
+
+inject_invalid_status_read()
+{
+	# Inject an invalid status (0x375) on a READ
+	_nvme_enable_err_inject "$1" 0 100 1 0x375 1
+
+	dd if=/dev/"$1" of=/dev/null bs=512 count=1 iflag=direct \
+	    2> /dev/null 1>&2
+
+	_nvme_clear_err_inject "$1"
+
+	if ${nvme_verbose_errors}; then
+		dmesg -t | tail -2 | grep "Unknown (" | \
+		    sed 's/nvme.*://g'
+	else
+		dmesg -t | tail -2 | grep "Cmd(" | sed 's/I\/O Cmd/Read/g' | \
+		    sed 's/I\/O Error/Unknown/g' | \
+		    sed 's/nvme.*://g'
+	fi
+}
+
+inject_write_fault_write()
+{
+	# Inject a 'Write Fault' 0x280 status error on a WRITE
+	_nvme_enable_err_inject "$1" 0 100 1 0x280 1
+
+	dd if=/dev/zero of=/dev/"$1" bs=512 count=1 oflag=direct \
+	    2> /dev/null 1>&2
+
+	_nvme_clear_err_inject "$1"
+
+	if ${nvme_verbose_errors}; then
+		dmesg -t | tail -2 | grep "Write Fault (" | \
+		    sed 's/nvme.*://g'
+	else
+		dmesg -t | tail -2 | grep "Cmd(" | sed 's/I\/O Cmd/Write/g' | \
+		    sed 's/I\/O Error/Write Fault/g' | \
+		    sed 's/nvme.*://g'
+	fi
+}
+
+inject_access_denied_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_clear_err_inject "$1"
+
+	if ${nvme_verbose_errors}; then
+		dmesg -t | tail -1 | grep "Access Denied (" | \
+		    sed 's/nvme.*://g'
+	else
+		dmesg -t | tail -1 | grep "Admin Cmd(" | \
+		    sed 's/Admin Cmd/Identify/g' | \
+		    sed 's/I\/O Error/Access Denied/g' | \
+		    sed 's/nvme.*://g'
+	fi
+}
+
+inject_invalid_cmd_admin()
+{
+	# Inject a 'Invalid Command Opcode' (0x1) on an invalid command (0x96)
+	 _nvme_enable_err_inject "$1" 0 100 1 0x1 1
+
+	nvme admin-passthru /dev/"$1" --opcode=0x96 --data-len=4096 \
+	    --cdw10=1 -r 2> /dev/null 1>&2
+
+	_nvme_clear_err_inject "$1"
+
+	if ${nvme_verbose_errors}; then
+		dmesg -t | tail -1 | grep "Invalid Command Opcode (" | \
+		    sed 's/nvme.*://g'
+	else
+		dmesg -t | tail -1 | grep "Admin Cmd(" | \
+		    sed 's/Admin Cmd/Unknown/g' | \
+		    sed 's/I\/O Error/Invalid Command Opcode/g' | \
+		    sed 's/nvme.*://g'
+	fi
+}
+
+test_device() {
+	local nvme_verbose_errors
+	local ns_dev
+	local ctrl_dev
+
+	echo "Running ${TEST_NAME}"
+
+	if _have_kernel_option NVME_VERBOSE_ERRORS; then
+		nvme_verbose_errors=true
+	else
+		unset SKIP_REASON
+		nvme_verbose_errors=false
+	fi
+
+	ns_dev=${TEST_DEV##*/}
+	ctrl_dev=${ns_dev%n*}
+
+	_nvme_err_inject_setup "${ns_dev}" "${ctrl_dev}"
+
+	inject_unrec_read_read "${ns_dev}"
+	inject_invalid_status_read "${ns_dev}"
+	inject_write_fault_write "${ns_dev}"
+
+	inject_access_denied_identify "${ctrl_dev}"
+	inject_invalid_cmd_admin "${ctrl_dev}"
+
+	_nvme_err_inject_cleanup "${ns_dev}" "${ctrl_dev}"
+
+	echo "Test complete"
+}
diff --git a/tests/nvme/039.out b/tests/nvme/039.out
new file mode 100644
index 000000000000..162935eb1d7b
--- /dev/null
+++ b/tests/nvme/039.out
@@ -0,0 +1,7 @@
+Running nvme/039
+ 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 
+ Unknown(0x96), Invalid Command Opcode (sct 0x0 / sc 0x1) DNR 
+Test complete
-- 
2.27.0

Re: [PATCH v3 blktests 1/2] tests/nvme: add helper routines to use error injector

[Shinichiro Kawasaki]

On May 13, 2022 / 08:52, Alan Adamson wrote:
> nvme tests can use these helper routines to setup and use
> the nvme error injector.
> 
> Signed-off-by: Alan Adamson <alan.adamson@oracle.com>
> ---
>  tests/nvme/rc | 44 ++++++++++++++++++++++++++++++++++++++++++++
>  1 file changed, 44 insertions(+)
> 
> diff --git a/tests/nvme/rc b/tests/nvme/rc
> index 3c38408a0bfe..c49a3c5d78da 100644
> --- a/tests/nvme/rc
> +++ b/tests/nvme/rc
> @@ -375,3 +375,47 @@ _discovery_genctr() {
>  	_nvme_discover "${nvme_trtype}" |
>  		sed -n -e 's/^.*Generation counter \([0-9]\+\).*$/\1/p'
>  }
> +
> +declare -A NS_DEV_FAULT_INJECT_SAVE
> +declare -A CTRL_DEV_FAULT_INJECT_SAVE
> +
> +_nvme_err_inject_setup()
> +{
> +        local a
> +
> +        for a in /sys/kernel/debug/"$1"/fault_inject/*; do
> +                NS_DEV_FAULT_INJECT_SAVE[${a}]=$(<"${a}")
> +        done
> +
> +        for a in /sys/kernel/debug/"$2"/fault_inject/*; do
> +                CTRL_DEV_FAULT_INJECT_SAVE[${a}]=$(<"${a}")
> +        done
> +}
> +
> +_nvme_err_inject_cleanup()
> +{
> +        local a
> +
> +        for a in /sys/kernel/debug/"${ns_dev}"/fault_inject/*; do
> +                echo "${NS_DEV_FAULT_INJECT_SAVE[${a}]}" > "${a}"
> +		echo ${a} $(<"${a}") >> /tmp/iii
> +        done
> +        for a in /sys/kernel/debug/"${ctrl_dev}"/fault_inject/*; do
> +                echo "${CTRL_DEV_FAULT_INJECT_SAVE[${a}]}" > "${a}"
> +        done
> +}

Thanks for separating out the helper functions.

${ns_dev} and ${ctrl_dev} should be ${1} and ${2}, and a debug code is left.
'make check' finds out them. Also, I wish to have an empty line between two for
blocks in same manner as _nvme_err_inject_setup().

> +
> +_nvme_enable_err_inject()
> +{
> +        echo "$2" > /sys/kernel/debug/"$1"/fault_inject/verbose
> +        echo "$3" > /sys/kernel/debug/"$1"/fault_inject/probability
> +        echo "$4" > /sys/kernel/debug/"$1"/fault_inject/dont_retry
> +        echo "$5" > /sys/kernel/debug/"$1"/fault_inject/status
> +        echo "$6" > /sys/kernel/debug/"$1"/fault_inject/times
> +}
> +
> +_nvme_clear_err_inject()

To be paired with _nvme_enable_err_inject(), _nvme_disable_err_inject() would be
the better name?

> +{
> +        echo 0 > /sys/kernel/debug/"$1"/fault_inject/probability
> +        echo 0 > /sys/kernel/debug/"$1"/fault_inject/times
> +}
> -- 
> 2.27.0
> 

-- 
Best Regards,
Shin'ichiro Kawasaki

Re: [PATCH v3 blktests 2/2] tests/nvme: add tests for error logging

[Shinichiro Kawasaki]

On May 13, 2022 / 08:52, Alan Adamson wrote:
> Test nvme error logging by injecting errors. Kernel must have FAULT_INJECTION
> and FAULT_INJECTION_DEBUG_FS configured to use error injector. Tests can be
> run with or without NVME_VERBOSE_ERRORS configured.
> 
> Signed-off-by: Alan Adamson <alan.adamson@oracle.com>
> Signed-off-by: Chaitanya Kulkarni <kch@nvidia.com>
> ---
>  tests/nvme/039     | 152 +++++++++++++++++++++++++++++++++++++++++++++
>  tests/nvme/039.out |   7 +++
>  2 files changed, 159 insertions(+)
>  create mode 100755 tests/nvme/039
>  create mode 100644 tests/nvme/039.out
> 
> diff --git a/tests/nvme/039 b/tests/nvme/039
> new file mode 100755
> index 000000000000..dd216cbb2ef0
> --- /dev/null
> +++ b/tests/nvme/039
> @@ -0,0 +1,152 @@
> +#!/bin/bash
> +# SPDX-License-Identifier: GPL-3.0+
> +# Copyright (C) 2022 Oracle and/or its affiliates
> +#
> +# Test nvme error logging by injecting errors. Kernel must have FAULT_INJECTION
> +# and FAULT_INJECTION_DEBUG_FS configured to use error injector. Tests can be
> +# run with or without NVME_VERBOSE_ERRORS configured.
> +#
> +# Test for commit bd83fe6f2cd2 ("nvme: add verbose error logging").
> +
> +. tests/nvme/rc
> +DESCRIPTION="test error logging"
> +QUICK=1
> +
> +requires() {
> +	_nvme_requires
> +	_have_kernel_option FAULT_INJECTION && \
> +	    _have_kernel_option FAULT_INJECTION_DEBUG_FS
> +}
> +
> +inject_unrec_read_read()

This new function name looks a bit weird for me. How about to have 'on' between
the error to inject and the command to be injected? Such as,
'inject_unrec_read_on_read'. Same comment on other three inject_*() functions.

> +{
> +	# Inject a 'Unrecovered Read Error' (0x281) status error on a READ
> +	_nvme_enable_err_inject "$1" 0 100 1 0x281 1
> +
> +	dd if=/dev/"$1" of=/dev/null bs=512 count=1 iflag=direct \
> +	    2> /dev/null 1>&2
> +
> +	_nvme_clear_err_inject "$1"

Nit: let's have one empty line here.

> +	if ${nvme_verbose_errors}; then
> +		dmesg -t | tail -2 | grep "Unrecovered Read Error (" | \
> +		    sed 's/nvme.*://g'
> +	else
> +		dmesg -t | tail -2 | grep "Cmd(" | sed 's/I\/O Cmd/Read/g' | \
> +		    sed 's/I\/O Error/Unrecovered Read Error/g' | \
> +		    sed 's/nvme.*://g'
> +	fi
> +}
> +
> +inject_invalid_status_read()
> +{
> +	# Inject an invalid status (0x375) on a READ
> +	_nvme_enable_err_inject "$1" 0 100 1 0x375 1
> +
> +	dd if=/dev/"$1" of=/dev/null bs=512 count=1 iflag=direct \
> +	    2> /dev/null 1>&2
> +
> +	_nvme_clear_err_inject "$1"
> +
> +	if ${nvme_verbose_errors}; then
> +		dmesg -t | tail -2 | grep "Unknown (" | \
> +		    sed 's/nvme.*://g'
> +	else
> +		dmesg -t | tail -2 | grep "Cmd(" | sed 's/I\/O Cmd/Read/g' | \
> +		    sed 's/I\/O Error/Unknown/g' | \
> +		    sed 's/nvme.*://g'
> +	fi
> +}
> +
> +inject_write_fault_write()
> +{
> +	# Inject a 'Write Fault' 0x280 status error on a WRITE
> +	_nvme_enable_err_inject "$1" 0 100 1 0x280 1
> +
> +	dd if=/dev/zero of=/dev/"$1" bs=512 count=1 oflag=direct \
> +	    2> /dev/null 1>&2
> +
> +	_nvme_clear_err_inject "$1"
> +
> +	if ${nvme_verbose_errors}; then
> +		dmesg -t | tail -2 | grep "Write Fault (" | \
> +		    sed 's/nvme.*://g'
> +	else
> +		dmesg -t | tail -2 | grep "Cmd(" | sed 's/I\/O Cmd/Write/g' | \
> +		    sed 's/I\/O Error/Write Fault/g' | \
> +		    sed 's/nvme.*://g'
> +	fi
> +}
> +
> +inject_access_denied_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_clear_err_inject "$1"
> +
> +	if ${nvme_verbose_errors}; then
> +		dmesg -t | tail -1 | grep "Access Denied (" | \
> +		    sed 's/nvme.*://g'
> +	else
> +		dmesg -t | tail -1 | grep "Admin Cmd(" | \
> +		    sed 's/Admin Cmd/Identify/g' | \
> +		    sed 's/I\/O Error/Access Denied/g' | \
> +		    sed 's/nvme.*://g'
> +	fi
> +}
> +
> +inject_invalid_cmd_admin()
> +{
> +	# Inject a 'Invalid Command Opcode' (0x1) on an invalid command (0x96)
> +	 _nvme_enable_err_inject "$1" 0 100 1 0x1 1
> +
> +	nvme admin-passthru /dev/"$1" --opcode=0x96 --data-len=4096 \
> +	    --cdw10=1 -r 2> /dev/null 1>&2
> +
> +	_nvme_clear_err_inject "$1"
> +
> +	if ${nvme_verbose_errors}; then
> +		dmesg -t | tail -1 | grep "Invalid Command Opcode (" | \
> +		    sed 's/nvme.*://g'
> +	else
> +		dmesg -t | tail -1 | grep "Admin Cmd(" | \
> +		    sed 's/Admin Cmd/Unknown/g' | \
> +		    sed 's/I\/O Error/Invalid Command Opcode/g' | \
> +		    sed 's/nvme.*://g'
> +	fi
> +}
> +
> +test_device() {
> +	local nvme_verbose_errors
> +	local ns_dev
> +	local ctrl_dev
> +
> +	echo "Running ${TEST_NAME}"
> +
> +	if _have_kernel_option NVME_VERBOSE_ERRORS; then
> +		nvme_verbose_errors=true
> +	else
> +		unset SKIP_REASON
> +		nvme_verbose_errors=false
> +	fi
> +
> +	ns_dev=${TEST_DEV##*/}
> +	ctrl_dev=${ns_dev%n*}
> +
> +	_nvme_err_inject_setup "${ns_dev}" "${ctrl_dev}"
> +
> +	inject_unrec_read_read "${ns_dev}"
> +	inject_invalid_status_read "${ns_dev}"
> +	inject_write_fault_write "${ns_dev}"
> +
> +	inject_access_denied_identify "${ctrl_dev}"
> +	inject_invalid_cmd_admin "${ctrl_dev}"
> +
> +	_nvme_err_inject_cleanup "${ns_dev}" "${ctrl_dev}"
> +
> +	echo "Test complete"
> +}
> diff --git a/tests/nvme/039.out b/tests/nvme/039.out
> new file mode 100644
> index 000000000000..162935eb1d7b
> --- /dev/null
> +++ b/tests/nvme/039.out
> @@ -0,0 +1,7 @@
> +Running nvme/039
> + 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 
> + Unknown(0x96), Invalid Command Opcode (sct 0x0 / sc 0x1) DNR 
> +Test complete
> -- 
> 2.27.0
> 

-- 
Best Regards,
Shin'ichiro Kawasaki