From cbedba7e1752ea9eefdae8320e6ac3ec22901c5d Mon Sep 17 00:00:00 2001
From: Marc Herbert <marc.herbert@intel.com>
Date: Thu, 6 Aug 2020 23:41:32 -0700
Subject: [PATCH 1/2] lib.sh: make logger init function return non-zero on
 failure

Incomplete fix for #298: helps only when logger is not found or not
executable. Print a warning and abort tests if they requested logging
_and_ they use set -e _and_ they don't explicitly ignore the error.

Also get rid of $loggerBin variable that made the logic more
complicated, now use $SOFLOGGER only.

Signed-off-by: Marc Herbert <marc.herbert@intel.com>
---
 case-lib/lib.sh | 23 +++++++++++++++++------
 1 file changed, 17 insertions(+), 6 deletions(-)

diff --git a/case-lib/lib.sh b/case-lib/lib.sh
index 60daee8b..3f8c6719 100644
--- a/case-lib/lib.sh
+++ b/case-lib/lib.sh
@@ -92,25 +92,36 @@ func_lib_start_log_collect()
         return 1
     }
 
-    local loggerBin="" logfile="" logopt="-t"
-    [[ "$SOFLOGGER" ]] && loggerBin=$SOFLOGGER || loggerBin=$(command -v sof-logger)
+    local logfile="" logopt="-t"
+
+    if [ -z "$SOFLOGGER" ]; then
+        SOFLOGGER=$(command -v sof-logger) || {
+            dlogw 'No sof-logger found in PATH'
+            return 1
+        }
+    fi
+
+    test -x "$SOFLOGGER" || {
+        dlogw "$SOFLOGGER not found or not executable"
+        return 2
+    }
+
     if [ "X$is_etrace" == "X0" ];then
         logfile=$LOG_ROOT/slogger.txt
     else
         logfile=$LOG_ROOT/etrace.txt
         logopt=""
     fi
-    [[ ! "$loggerBin" ]] && return
-    SOFLOGGER=$loggerBin
+
     if func_hijack_setup_sudo_level ;then
         # shellcheck disable=SC2034 # external script will use it
         SOF_LOG_COLLECT=1
     else
         >&2 dlogw "without sudo permission to run $SOFLOGGER command"
-        return
+        return 3
     fi
 
-    sudo "$loggerBin $logopt -l $ldcFile -o $logfile" 2>/dev/null &
+    sudo "$SOFLOGGER $logopt -l $ldcFile -o $logfile" 2>/dev/null &
 }
 
 func_lib_check_sudo()

From 0e78de45a93126b5aae09a5547158871ff248ff5 Mon Sep 17 00:00:00 2001
From: Marc Herbert <marc.herbert@intel.com>
Date: Thu, 10 Sep 2020 12:41:47 -0700
Subject: [PATCH 2/2] logger: stop discarding all error messages and fix the
 cleanup code

Likely to avoid the shell printing a "Killed logger" message, lib.sh was
starting the logger with a "2>/dev/null" redirection. Here's a sample
list of logger errors that have been discarded by this redirection since
forever:

 error: Unable to open ldc file /etc/sof/sof-apl.ldc
 error: Unable to open in file /sys/kernel/debug/sof/trace
 error: Unable to open version file /sys/kernel/debug/sof/fw_version

Remove this 2>/dev/null redirection which was an insane price to pay for
making the logs "beautiful".

While not important, let's make the logs "beautiful" anyway because we
can: thanks to -SIGINT instead of SIGKILL. SIGKILL (-9) does not give a
any chance for the logger to exit cleanly, flus outputs etc. and is
only ever used as a last resort, see "man systemd.kill" etc.

Also log the logger command complete with parameters and the size of its
output at the end.

Signed-off-by: Marc Herbert <marc.herbert@intel.com>
---
 case-lib/hijack.sh | 15 +++++++++++++--
 case-lib/lib.sh    |  7 +++++--
 2 files changed, 18 insertions(+), 4 deletions(-)

diff --git a/case-lib/hijack.sh b/case-lib/hijack.sh
index 18c8f288..335f985e 100644
--- a/case-lib/hijack.sh
+++ b/case-lib/hijack.sh
@@ -30,12 +30,23 @@ function func_exit_handler()
             func_lib_start_log_collect 1
             sleep 1s
         }
-        local loggerBin; loggerBin=$(basename "$SOFLOGGER")
-        sudo pkill -9 "$loggerBin" 2>/dev/null || {
+
+        local loggerBin wcLog; loggerBin=$(basename "$SOFLOGGER")
+        # INT doesn't print any "Killed" message in non-interactive mode
+        sudo pkill -INT "$loggerBin" || {
             dloge "sof-logger was already dead"
             exit_status=1
         }
         sleep 1s
+        if pgrep "$loggerBin"; then
+            dloge "$loggerBin resisted pkill -INT, using -KILL"
+            sudo pkill -KILL "$loggerBin"
+            exit_status=2
+        fi
+        # logfile is set in a different file: lib.sh
+        # shellcheck disable=SC2154
+        wcLog=$(wc -l "$logfile")
+        dlogi "nlines=$wcLog"
     fi
     # when case ends, store kernel log
     # /var/log/kern.log format:
diff --git a/case-lib/lib.sh b/case-lib/lib.sh
index 3f8c6719..9def0c27 100644
--- a/case-lib/lib.sh
+++ b/case-lib/lib.sh
@@ -92,7 +92,7 @@ func_lib_start_log_collect()
         return 1
     }
 
-    local logfile="" logopt="-t"
+    local logopt="-t"
 
     if [ -z "$SOFLOGGER" ]; then
         SOFLOGGER=$(command -v sof-logger) || {
@@ -121,7 +121,10 @@ func_lib_start_log_collect()
         return 3
     fi
 
-    sudo "$SOFLOGGER $logopt -l $ldcFile -o $logfile" 2>/dev/null &
+    local loggerCmd="$SOFLOGGER $logopt -l $ldcFile -o $logfile"
+    dlogi "Starting $loggerCmd"
+    # Cleaned up by func_exit_handler() in hijack.sh
+    sudo "$loggerCmd" &
 }
 
 func_lib_check_sudo()