case-lib: refactor kernel logs collecting

Start collecting kernel logs in the beggining of the test and run
collection in the background.

Signed-off-by: Emilia Kurdybelska <emiliax.kurdybelska@intel.com>

Author: ekurdybx

case-lib/hijack.sh

@@ -12,6 +12,8 @@ function func_exit_handler()
 
     dlogi "Starting func_exit_handler($exit_status)"
 
+    finish_kmsg_collection
+
     func_lib_check_and_disable_pipewire
 
     # call trace
@@ -134,32 +136,6 @@ function func_exit_handler()
         storage_checks || exit_status=1
     fi
 
-    local journalctl_logs="$LOG_ROOT/dmesg.txt"
-    if [[ "$KERNEL_CHECKPOINT" =~ ^[0-9]{10} ]]; then
-        # Do not collect the entire duration of the test but only the
-        # last iteration.
-        dlogi "Save kernel messages since ${KERNEL_CHECKPOINT} to ${journalctl_logs}"
-        journalctl_cmd --since=@"$KERNEL_CHECKPOINT" > "${journalctl_logs}"
-    elif [[ "$KERNEL_CHECKPOINT" == "disabled" ]]; then
-        dlogi "Save all kernel messages to ${journalctl_logs}"
-        journalctl_cmd > "${journalctl_logs}"
-    else
-       dloge 'Kernel check point "KERNEL_CHECKPOINT" is not properly set'
-       dloge "KERNEL_CHECKPOINT=$KERNEL_CHECKPOINT"
-       test "$exit_status" -ne 0 || exit_status=1
-    fi
-    if test -s "${journalctl_logs}"; then
-       wcLog=$(wc -l "${journalctl_logs}")
-       dlogi  "nlines=$wcLog"
-    else
-       dlogw "Empty ${journalctl_logs}"
-    fi
-    # Make sure the logs are written on disk just in case of DUT power reset.
-    sync
-
-    # After log collected, KERNEL_CHECKPOINT will not be used any more
-    unset KERNEL_CHECKPOINT
-
     # get ps command result as list
     local -a cmd_lst
     # $$ as current script pid

case-lib/lib.sh

@@ -83,6 +83,9 @@ minvalue() { printf '%d' $(( "$1" < "$2"  ? "$1" : "$2" )); }
 #
 start_test()
 {
+    setup_kernel_check_point
+    func_kmsg_collect
+
     if [ "$SOF_TEST_PIPEWIRE" == true ]; then
         func_lib_enable_pipewire
     fi
@@ -97,7 +100,7 @@ start_test()
     }
 
     # func_exit_handler() is in hijack.sh
-    trap 'func_exit_handler $?' EXIT
+    trap 'func_exit_handler $?' EXIT SIGTERM
 
     if test -z "$MAX_WAIT_FW_LOADING"; then
         local _pltf; _pltf=$("$SCRIPT_HOME/tools/sof-dump-status.py" -p)
@@ -157,7 +160,6 @@ start_test()
     local start_msg="$prefix: starting"
     dlogi "$start_msg"
     logger -p user.info "$start_msg"
-
 }
 
 # See high-level description in start_test header above
@@ -198,6 +200,24 @@ stop_test()
 }
 
 
+finish_kmsg_collection()
+{
+    dlogi "Finishing dmesg collection"
+    kill -TERM "$KMSG_PID"
+    wait "$KMSG_PID"
+
+    local journalctl_logs="$LOG_ROOT/dmesg.txt"
+    if test -s "${journalctl_logs}"; then
+       wcLog=$(wc -l "${journalctl_logs}")
+       dlogi  "nlines=$wcLog"
+    else
+       dlogw "Empty ${journalctl_logs}"
+    fi
+    # Make sure the logs are written on disk just in case of DUT power reset.
+    sync
+}
+
+
 ktime()
 {
     # Keep it coarse because of various delays.
@@ -276,7 +296,9 @@ setup_kernel_check_point()
     # appear in the next one, see comments in config.sh.  Add 3 extra
     # second to account for our own, sof-test delays after PASS/FAIL
     # decision: time spent collecting logs etc.
-    if [ -z "$KERNEL_CHECKPOINT" ]; then
+    if [[ "$KERNEL_CHECKPOINT" == "disabled" ]]; then
+        dlogi "KERNEL_CHECKPOINT already set as DISABLED"
+    elif [ -z "$KERNEL_CHECKPOINT" ]; then
         KERNEL_CHECKPOINT=$(($(date +%s) - SOF_TEST_INTERVAL - 3))
     else
         # Not the first time we are called so this is a test
@@ -408,6 +430,22 @@ func_mtrace_collect()
     sudo bash -c "${mtraceCmd[*]} &" >& "$clogfile"
 }
 
+func_kmsg_collect() {
+    local journalctl_logs="$LOG_ROOT/dmesg.txt"
+
+    if [[ "$KERNEL_CHECKPOINT" =~ ^[0-9]{10} ]]; then
+        dlogi "Saving kernel messages since ${KERNEL_CHECKPOINT} to ${journalctl_logs}"
+        journalctl_cmd --since=@"$KERNEL_CHECKPOINT" -f >> "${journalctl_logs}" &
+    elif [[ "$KERNEL_CHECKPOINT" == "disabled" ]]; then
+        dlogi "KERNEL_CHECKPOINT set as DISABLED, saving all kernel messages"
+        journalctl_cmd -f >> "${journalctl_logs}" &
+    else
+        dlogi "KERNEL_CHECKPOINT is not properly set, saving all kernel messages"
+        journalctl_cmd -f >> "${journalctl_logs}" &
+    fi
+    KMSG_PID=$!
+}
+
 func_lib_log_post_process()
 {
     # SyS-T log output a Zephyr feature, no need postprocess

test-case/check-8bit-play-rec.sh

@@ -116,7 +116,6 @@ main()
 
     logger_disabled || func_lib_start_log_collect
 
-    setup_kernel_check_point
     func_lib_check_sudo
     func_pipeline_export "$tplg" "type:any"
 

test-case/check-alsa-conformance.sh

@@ -325,8 +325,6 @@ main()
 {
   init_globals
 
-  setup_kernel_check_point
-
   start_test
 
   check_alsa_conformance_suite

test-case/check-alsabat.sh

@@ -61,7 +61,6 @@ OPT_NAME['s']='sof-logger'      OPT_DESC['s']="Open sof-logger trace the data wi
 OPT_HAS_ARG['s']=0             OPT_VAL['s']=1
 
 func_opt_parse_option "$@"
-setup_kernel_check_point
 
 pcm_p=${OPT_VAL['p']}
 pcm_c=${OPT_VAL['c']}

test-case/check-audio-equalizer.sh

@@ -44,7 +44,6 @@ func_pipeline_export "$tplg" "eq:any"
 sofcard=${SOFCARD:-0}
 
 start_test
-setup_kernel_check_point
 
 # Test equalizer
 func_test_eq()

test-case/check-capture.sh

@@ -75,7 +75,6 @@ if [[ -n "$new_tplg_filename" && "$TPLG" != *nocodec* ]]; then
 fi
 logger_disabled || func_lib_start_log_collect
 
-setup_kernel_check_point
 func_lib_check_sudo
 func_pipeline_export "$tplg" "type:capture & ${OPT_VAL['S']}"
 

test-case/check-float-play-rec.sh

@@ -91,7 +91,6 @@ main()
 
     logger_disabled || func_lib_start_log_collect
 
-    setup_kernel_check_point
     func_lib_check_sudo
     func_pipeline_export "$tplg" "type:any"
 

test-case/check-fw-echo-reference.sh

@@ -44,7 +44,6 @@ start_test
 logger_disabled || func_lib_start_log_collect
 
 func_pipeline_export "$tplg" "echo:any"
-setup_kernel_check_point
 
 if [ "$PIPELINE_COUNT" != "2" ]; then
     die "Only detect $PIPELINE_COUNT pipeline(s) from topology, but two are needed"
@@ -66,7 +65,7 @@ do
     fi
 done
 
-for i in $(seq 1 $loop_cnt)
+for i in $(seq 1 "$loop_cnt")
 do
     for fmt in $fmts
     do

test-case/check-ipc-flood.sh

@@ -28,7 +28,6 @@ OPT_NAME['l']='loop'     OPT_DESC['l']='loop count'
 OPT_HAS_ARG['l']=1         OPT_VAL['l']=1
 
 func_opt_parse_option "$@"
-setup_kernel_check_point
 
 lpc_loop_cnt=${OPT_VAL['c']}
 ipc_flood_dfs=${OPT_VAL['f']}
@@ -47,12 +46,12 @@ sof-kernel-dump.sh | grep sof-audio | grep -q "Firmware debug" ||
 func_lib_check_sudo
 
 dlogi "Check $ipc_flood_dfs"
-sudo test -e $ipc_flood_dfs ||
+sudo test -e "$ipc_flood_dfs" ||
   skip_test "${BASH_SOURCE[0]} need $ipc_flood_dfs to run the test case"
 
 dlogi "Running ipc flood test!"
 
-for i in $(seq 1 $loop_cnt)
+for i in $(seq 1 "$loop_cnt")
 do
     # TODO: use journalctl to replace dmesg
     # cleanup dmesg buffer for each iteration