[PATCH blktests] nvme/039: avoid failure by error message rate limit

[Shin'ichiro Kawasaki]

From: Shin'ichiro Kawasaki <shinichiro.kawasaki at wdc.com>

The test case nvme/039 tests that expected error messages are printed
for errors injected to the nvme driver. However, the test case fails by
chance when previous test cases generate many error messages. In this
case, the kernel function pr_err_ratelimited() may suppress the error
messages that the test case expects. Also, it may print messages that
the test case does not expect, such as "blk_print_req_error: xxxx
callbacks suppressed".

To avoid the failure, make two improvements for the test case. Firstly,
wait DEFAULT_RATE_LIMIT seconds at the beginning of the test to ensure
the expected error messages are not suppressed. Secondly, exclude the
unexpected message for the error message check. Introduce a helper
function last_dmesg() for the second improvement.

Fixes: 9accb5f86670 ("tests/nvme: add tests for error logging")
Signed-off-by: Shin'ichiro Kawasaki <shinichiro.kawasaki at wdc.com>
Link: https://lore.kernel.org/linux-block/5vnpdeocos6k4nmh6ewh7ltqz7b6wuemzcmqflfkybejssewkh@edtqm3t4w3zv/
---
 tests/nvme/039 | 28 ++++++++++++++++++++--------
 1 file changed, 20 insertions(+), 8 deletions(-)

diff --git a/tests/nvme/039 b/tests/nvme/039
index 11d6d24..f327b54 100755
--- a/tests/nvme/039
+++ b/tests/nvme/039
@@ -18,6 +18,15 @@ requires() {
 	    _have_kernel_option FAULT_INJECTION_DEBUG_FS
 }
 
+# Get the last dmesg lines as many as specified. Exclude the lines to indicate
+# suppression by rate limit.
+last_dmesg()
+{
+	local nr_lines=$1
+
+	dmesg -t | grep -v "callbacks suppressed" | tail "-$nr_lines"
+}
+
 inject_unrec_read_on_read()
 {
 	# Inject a 'Unrecovered Read Error' (0x281) status error on a READ
@@ -29,10 +38,10 @@ inject_unrec_read_on_read()
 	_nvme_disable_err_inject "$1"
 
 	if ${nvme_verbose_errors}; then
-		dmesg -t | tail -2 | grep "Unrecovered Read Error (" | \
+		last_dmesg 2 | grep "Unrecovered Read Error (" | \
 		    sed 's/nvme.*://g'
 	else
-		dmesg -t | tail -2 | grep "Cmd(" | sed 's/I\/O Cmd/Read/g' | \
+		last_dmesg 2 | grep "Cmd(" | sed 's/I\/O Cmd/Read/g' | \
 		    sed 's/I\/O Error/Unrecovered Read Error/g' | \
 		    sed 's/nvme.*://g'
 	fi
@@ -49,10 +58,10 @@ inject_invalid_status_on_read()
 	_nvme_disable_err_inject "$1"
 
 	if ${nvme_verbose_errors}; then
-		dmesg -t | tail -2 | grep "Unknown (" | \
+		last_dmesg 2 | grep "Unknown (" | \
 		    sed 's/nvme.*://g'
 	else
-		dmesg -t | tail -2 | grep "Cmd(" | sed 's/I\/O Cmd/Read/g' | \
+		last_dmesg 2 | grep "Cmd(" | sed 's/I\/O Cmd/Read/g' | \
 		    sed 's/I\/O Error/Unknown/g' | \
 		    sed 's/nvme.*://g'
 	fi
@@ -69,10 +78,10 @@ inject_write_fault_on_write()
 	_nvme_disable_err_inject "$1"
 
 	if ${nvme_verbose_errors}; then
-		dmesg -t | tail -2 | grep "Write Fault (" | \
+		last_dmesg 2 | grep "Write Fault (" | \
 		    sed 's/nvme.*://g'
 	else
-		dmesg -t | tail -2 | grep "Cmd(" | sed 's/I\/O Cmd/Write/g' | \
+		last_dmesg 2 | grep "Cmd(" | sed 's/I\/O Cmd/Write/g' | \
 		    sed 's/I\/O Error/Write Fault/g' | \
 		    sed 's/nvme.*://g'
 	fi
@@ -90,10 +99,10 @@ inject_access_denied_on_identify()
 	_nvme_disable_err_inject "$1"
 
 	if ${nvme_verbose_errors}; then
-		dmesg -t | tail -1 | grep "Access Denied (" | \
+		last_dmesg 1 | grep "Access Denied (" | \
 		    sed 's/nvme.*://g'
 	else
-		dmesg -t | tail -1 | grep "Admin Cmd(" | \
+		last_dmesg 1 | grep "Admin Cmd(" | \
 		    sed 's/Admin Cmd/Identify/g' | \
 		    sed 's/I\/O Error/Access Denied/g' | \
 		    sed 's/nvme.*://g'
@@ -139,6 +148,9 @@ test_device() {
 
 	_nvme_err_inject_setup "${ns_dev}" "${ctrl_dev}"
 
+	# wait DEFAULT_RATELIMIT_INTERVAL=5 seconds to ensure errors are printed
+	sleep 5
+
 	inject_unrec_read_on_read "${ns_dev}"
 	inject_invalid_status_on_read "${ns_dev}"
 	inject_write_fault_on_write "${ns_dev}"
-- 
2.39.2