From 1cf98eab66f62d42a4bbbe951113d299bfc1ddc2 Mon Sep 17 00:00:00 2001
From: Marc Herbert <marc.herbert@intel.com>
Date: Mon, 26 Apr 2021 17:05:29 -0700
Subject: [PATCH] check-sof-logger: rewrite most of it so it can actually find
 bugs

Probably the main change is fixing the huge etrace test gaps #321 and
https://github.com/thesofproject/sof/issues/3281

Also fixes DMA trace gaps #297 and #298

I initial tried to preserve some of the existing code but it was just
too bad. PR #161 / commit 7274f490b78 seemed especially bad:

- It tried to ignore a specific `ll drift` error but instead it filtered
out almost every log statement out of... stderr, that does not have show
log statements!! (Just for the record this `ll drift` error has been
downgraded to warning now, see
https://github.com/thesofproject/sof/pull/2686 and
https://github.com/thesofproject/sof/issues/3854)

- That same commit also added code that merely starts the DMA trace with
"there is an error below" (without failing the test) but that's eclipsed
by the entire log that follows. Later, the firmware started printing
ERROR every single time when the ERROR FW ABI prefix was introduced yet
no one ever noticed which proves how useless this prefix is was.

So remove this DMA trace prefix as the purpose of this test is - as
clearly stated in #167 - not to find firmware errors but errors with the
sof-logger itself (even though we never had anything looking at firmware
errors so far)

Don't grep for "error" on stderr: anything on stderr is a logger
failure (not a firmware failure).

Don't require whitespace before the TIMESTAMP header.

Add set -e.

Use shell functions.

Signed-off-by: Marc Herbert <marc.herbert@intel.com>
---
 test-case/check-sof-logger.sh | 140 +++++++++++++++++++++++-----------
 1 file changed, 95 insertions(+), 45 deletions(-)

diff --git a/test-case/check-sof-logger.sh b/test-case/check-sof-logger.sh
index f3775ddf..a51997eb 100755
--- a/test-case/check-sof-logger.sh
+++ b/test-case/check-sof-logger.sh
@@ -3,25 +3,29 @@
 ##
 ## Case Name: check-sof-logger
 ## Preconditions:
-##    sof-logger install in system path
-##    ldc file is in /etc/sof/
+##    sof-logger installed in system path
+##    ldc file is in /etc/sof/ or /lib/firmware
+##
 ## Description:
-##    Check debug tools sof-logger can success work
+##    Checks basic functionality of the sof-logger itself. Does not test
+##    the firmware, i.e., does NOT fail when errors are found in the
+##    logs.
+##
 ## Case step:
 ##    1. check sof-logger in system
 ##    2. check ldc file in system
 ##    3. run sof-logger
 ## Expect result:
-##    sof-logger already catch some thing
+##    sof-logger produces some output and did not fail
 ##
 
+set -e
+
 # shellcheck source=case-lib/lib.sh
 source "$(dirname "${BASH_SOURCE[0]}")"/../case-lib/lib.sh
 
 func_opt_parse_option "$@"
 
-#TODO: need to add arguments for user to give location for logger and ldc file
-
 setup_kernel_check_point
 
 # check sof-logger location
@@ -53,57 +57,103 @@ ldcFile=$(find_ldc_file) || die ".ldc file not found!"
 
 dlogi "Found file: $(md5sum "$ldcFile"|awk '{print $2, $1;}')"
 
+# These filenames are kept for backward-compatibility
+# DMA trace
 data_file=$LOG_ROOT/logger.data.txt
+# stderr
 error_file=$LOG_ROOT/logger.error.txt
 
-func_lib_check_sudo
+# etrace shared memory mailbox, newer feature.
+etrace_file=$LOG_ROOT/logger.etrace.txt
+etrace_stderr_file=$LOG_ROOT/logger.etrace_stderr.txt
 
-dlogi "Try to dump the dma trace log via sof-logger ..."
-# sof-logger errors will output to $error_file
-dlogc "sudo $loggerBin -t -l $ldcFile -o $data_file 2> $error_file &"
-sudo bash -c "'$loggerBin -t -l $ldcFile -o $data_file 2> $error_file &'"
-sleep 2
-dlogc "sudo pkill -9 $(basename "$loggerBin")"
-sudo pkill -9 "$(basename "$loggerBin")" 2> /dev/null
+func_lib_check_sudo
 
-func_logger_exit()
+run_loggers()
 {
-    local code=$1
+    local loggerPID etrace_exit
+
+    dlogi "Trying to get the DMA trace log with background sof-logger ..."
+    dlogc \
+    "sudo $loggerBin  -t -f 3 -l  $ldcFile  -o  $data_file  2>  $error_file  &"
+    sudo "$loggerBin" -t -f 3 -l "$ldcFile" -o "$data_file" 2> "$error_file" & loggerPID=$!
+
+    # This test is not really supposed to run while the DSP is busy at
+    # the same time, so $data_file should be short enough.
+    sleep 2
+
+    dlogi "Trying to get the etrace mailbox ..."
+    dlogc \
+    "sudo $loggerBin    -f 3 -l  $ldcFile  2>  $etrace_stderr_file  -o  $etrace_file"
+    sudo "$loggerBin"   -f 3 -l "$ldcFile" 2> "$etrace_stderr_file" -o "$etrace_file" ||
+        etrace_exit=$?
+
+    printf '\n'
+
+    dlogc "kill $loggerPID # DMA trace"
+    kill "$loggerPID"
+
+    return $etrace_exit
+}
 
-    for ftype in data error; do
-        printf '\n'
+# Dumps all logs before exiting
+print_logs_exit()
+{
+    local exit_code="$1" errmsg="$2"
+
+    # Print $errmsg twice: - once _after_ the (possibly long) logs
+    # because the end is where everyone logically looks atfirst when the
+    # test fails, and; - also now _before_ the logs in case something
+    # goes wrong and we don't make it until the end.
+    test -z "$errmsg" || dloge "$errmsg"
+
+    local bname
+    for ftype in data etrace error etrace_stderr; do
+        printf '\n\n'
+        bname="logger.$ftype.txt"
         dlogi "Log $ftype BEG::"
-        cat "$LOG_ROOT/logger.$ftype.log"
+        cat "$LOG_ROOT/$bname" || true # we already checked these
         dlogi "::END $ftype"
     done
-    exit "$code"
+    test -z "$errmsg" || dloge "$errmsg"
+    exit "$exit_code"
 }
 
-# check if we get any sof-logger errors
-logger_err=$(grep -i 'error' "$error_file")
-if [[ $logger_err ]]; then
-    dloge "No available log to export due to sof-logger errors."
-    func_logger_exit 1
-fi
+main()
+{
+    run_loggers ||
+        print_logs_exit 1 "Reading etrace failed, run_loggers returned $?"
 
-# '\.c\:[1-9]' to filter like '.c:6' this type keyword like:
-# [3017136.770833]  (11.302083) c0 SA  src/lib/agent.c:65  ERROR validate(), ll drift detected, delta = 25549
-fw_log_err=$(grep -i 'error' "$data_file" | grep -v '\.c\:[1-9]')
-
-# '[[:blank:]]TIMESTAMP.*CONTENT$' to filter the log header:
-# TIMESTAMP  DELTA C# COMPONENT  LOCATION  CONTENT
-if [[ ! $(sed -n '/TIMESTAMP.*CONTENT/p' "${data_file}") ]]; then
-    dloge "Log header not found in ${data_file}"
-    func_logger_exit 1
-# we catch error from fw log
-elif [[ $fw_log_err ]]; then
-    dloge "Error(s) found in firmware log ${data_file}"
-    func_logger_exit 1
-fi
+    local f
 
-if grep -i -q 'error' "$data_file" ; then
-    dlogw "Catch keyword 'ERROR' in firmware log"
-fi
+    for f in etrace_stderr error; do
+        local stderr_file="$LOG_ROOT/logger.$f.txt"
+        test -e "$stderr_file" || die "$stderr_file" not found
+        if test -s "$stderr_file"; then
+            print_logs_exit 1 "stderr $stderr_file is not empty"
+        fi
+    done
+
+    # Search for the log header, should be something like this:
+    # TIMESTAMP  DELTA C# COMPONENT  LOCATION  CONTENT
+    for f in etrace data; do
+        local tracef="$LOG_ROOT/logger.$f.txt"
+        test -e "$tracef" || die "$tracef" not found
+        # Other columns are optional
+        head -n 1 "$tracef" | grep -q 'COMPONENT.*CONTENT'  ||
+            print_logs_exit 1 "Log header not found in ${data_file}"
+
+        # See initial message SOF PR #3281 / SOF commit 67a0a69
+        grep -q 'dma-trace.c.*ERROR FW ABI.*tag.*hash' "$tracef" ||
+            print_logs_exit 1 "Initial ERROR FW ABI message not found in ${data_file}"
+    done
+
+    # This is a bit redundant with the previous test but does not hurt.
+    tail -n +2 "${data_file}" | grep -q '[^[:blank:]]' ||
+        print_logs_exit 1 "Nothing but the first line in DMA trace ${data_file}"
+
+    # Show all outputs even when everything went OK
+    print_logs_exit 0
+}
 
-# no error with sof-logger and no error in fw log
-func_logger_exit 0
+main "$@"