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

[Shinichiro Kawasaki]

On May 10, 2022 / 16:48, Sagi Grimberg wrote:
> 
> > > On 5/10/22 19:43, 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.
> > > > 
> > > > These test verify the functionality delivered by the follow:
> > > > 	commit bd83fe6f2cd2 ("nvme: add verbose error logging")
> > > > 
> > > > Signed-off-by: Alan Adamson <alan.adamson at oracle.com>
> > > > Signed-off-by: Chaitanya Kulkarni <kch at nvidia.com>
> > > > ---
> > > >    tests/nvme/039     | 185 +++++++++++++++++++++++++++++++++++++++++++++
> > > >    tests/nvme/039.out |   7 ++
> > > >    2 files changed, 192 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..e6d45a6e3fe5
> > > > --- /dev/null
> > > > +++ b/tests/nvme/039
> > > > @@ -0,0 +1,185 @@
> > > > +#!/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
> > > > +}
> > > > +
> > > > +declare -A NS_DEV_FAULT_INJECT_SAVE
> > > > +declare -A CTRL_DEV_FAULT_INJECT_SAVE
> > > > +
> > > > +save_err_inject_attr()
> > > > +{
> > > > +	local a
> > > > +
> > > > +	for a in /sys/kernel/debug/"${ns_dev}"/fault_inject/*; do
> > > > +		NS_DEV_FAULT_INJECT_SAVE[${a}]=$(<"${a}")
> > > > +	done
> > > > +	for a in /sys/kernel/debug/"${ctrl_dev}"/fault_inject/*; do
> > > > +		CTRL_DEV_FAULT_INJECT_SAVE[${a}]=$(<"${a}")
> > > > +	done
> > > > +}
> > > > +
> > > > +restore_err_inject_attr()
> > > > +{
> > > > +	local a
> > > > +
> > > > +	for a in /sys/kernel/debug/"${ns_dev}"/fault_inject/*; do
> > > > +		echo "${NS_DEV_FAULT_INJECT_SAVE[${a}]}" > "${a}"
> > > > +	done
> > > > +	for a in /sys/kernel/debug/"${ctrl_dev}"/fault_inject/*; do
> > > > +		echo "${CTRL_DEV_FAULT_INJECT_SAVE[${a}]}" > "${a}"
> > > > +	done
> > > > +}
> > > > +
> > > > +set_verbose_prob_retry()
> > > > +{
> > > > +	echo 0 > /sys/kernel/debug/"$1"/fault_inject/verbose
> > > > +	echo 100 > /sys/kernel/debug/"$1"/fault_inject/probability
> > > > +	echo 1 > /sys/kernel/debug/"$1"/fault_inject/dont_retry
> > > > +}
> > > > +
> > > > +set_status_time()
> > > > +{
> > > > +	echo "$1" > /sys/kernel/debug/"$3"/fault_inject/status
> > > > +	echo "$2" > /sys/kernel/debug/"$3"/fault_inject/times
> > > > +}
> > > > +
> > > > +inject_unrec_read_err()
> > > > +{
> > > > +	# Inject a 'Unrecovered Read Error' error on a READ
> > > > +	set_status_time 0x281 1 "$1"
> > > > +
> > > > +	dd if=/dev/"$1" of=/dev/null bs=512 count=1 iflag=direct \
> > > > +	    2> /dev/null 1>&2
> > > > +
> > > > +	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_read_err()
> > > > +{
> > > > +	# Inject a valid invalid error status (0x375) on a READ
> > > > +	set_status_time 0x375 1 "$1"
> > > > +
> > > > +	dd if=/dev/"$1" of=/dev/null bs=512 count=1 iflag=direct \
> > > > +	    2> /dev/null 1>&2
> > > > +
> > > > +	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()
> > > > +{
> > > > +	# Inject a 'Write Fault' error on a WRITE
> > > > +	set_status_time 0x280 1 "$1"
> > > > +
> > > > +	dd if=/dev/zero of=/dev/"$1" bs=512 count=1 oflag=direct \
> > > > +	    2> /dev/null 1>&2
> > > > +
> > > > +	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_id_admin()
> > > > +{
> > > > +	# Inject a valid (Identify) Admin command
> > > > +	set_status_time 0x286 1000 "$1"
> > > > +
> > > > +	nvme admin-passthru /dev/"$1" --opcode=0x06 --data-len=4096 \
> > > > +	    --cdw10=1 -r 2> /dev/null 1>&2
> > > > +
> > > > +	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()
> > > > +{
> > > > +	# Inject an invalid command (0x96)
> > > > +	set_status_time 0x1 1 "$1"
> > > > +
> > > > +	nvme admin-passthru /dev/"$1" --opcode=0x96 --data-len=4096 \
> > > > +	    --cdw10=1 -r 2> /dev/null 1>&2
> > > > +	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
> > > > +}
> > > > +
> > > 
> > > All of the above seems like they belong in common code...
> > 
> > So far, this nvme/039 is the only one user of the helper functions above. Do you
> > foresee that future new test cases in nvmeof-mp or srp group will use them?
> > 
> 
> I can absolutely see other tests inject errors. I meant that this code
> should live in nvme/rc

Thanks for clarification. So we expect two patches: one to add the helper
functions to nvme/rc, and the other to add this test case.

The inject_*() functions refer nvme_verbose_errors for dmesg filter, which is
defined in test_device(). That part needs a bit of rework to move to nvme/rc.

-- 
Best Regards,
Shin'ichiro Kawasaki