nvme/039: avoid failure by error message rate limit

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")
Link: https://lore.kernel.org/linux-block/5vnpdeocos6k4nmh6ewh7ltqz7b6wuemzcmqflfkybejssewkh@edtqm3t4w3zv/
Reviewed-by: Alan Adamson <alan.adamson@oracle.com>
Tested-by: Alan Adamson <alan.adamson@oracle.com>
Signed-off-by: Shin'ichiro Kawasaki <shinichiro.kawasaki@wdc.com>

diff --git a/tests/nvme/039 b/tests/nvme/039
index 11d6d24b6025e85a1f1f714ffbc9b494f205c432..f327b54a8d00f3c5fd3d0eef9b7e5ab171892f5d 100755 (executable)
--- 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}"