case-lib: refactor kernel logs collecting

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,23 @@ stop_test()
 }
 
 
+finish_kmsg_collection()
+{
+    dlogi "Finishing dmesg collection"
+    sudo pkill -9 journalctl
+
+    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 +295,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 +429,21 @@ 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
+}
+
 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

test-case/check-keyword-detection.sh

@@ -44,7 +44,6 @@ OPT_NAME['d']='duration'          OPT_DESC['d']='interrupt kwd pipeline in # sec
 OPT_HAS_ARG['d']=1                  OPT_VAL['d']=10
 
 func_opt_parse_option "$@"
-setup_kernel_check_point
 
 tplg=${OPT_VAL['t']}
 loop_cnt=${OPT_VAL['l']}
@@ -107,7 +106,7 @@ _restore_default_wov_config_bolb()
 # update the blob
 _update_blob(){
     new_blob=$test_dir"/new_blob"
-    [ $preamble_time -ge $history_depth ] || {
+    [ "$preamble_time" -ge "$history_depth" ] || {
         die "Warning: invalid arguments, preamble_time must be greater than or equal to history_depth"
     }
     awk -F, -v OFS=, '{if ( $4 == '"$def_pt"' && $7 == '"$def_hd"' ) $4='"$preamble_time"'; $7='"$history_depth"'}1' \

test-case/check-kmod-load-unload.sh

@@ -36,7 +36,6 @@ OPT_NAME['p']='pulseaudio'   OPT_DESC['p']='disable pulseaudio on the test proce
 OPT_HAS_ARG['p']=0             OPT_VAL['p']=1
 
 func_opt_parse_option "$@"
-setup_kernel_check_point
 
 start_test
 
@@ -45,11 +44,11 @@ loop_cnt=${OPT_VAL['l']}
 PATH="${PATH%%:*}/kmod:$PATH"
 func_lib_check_sudo 'unloading modules'
 
-if [ ${OPT_VAL['p']} -eq 1 ];then
+if [ "${OPT_VAL['p']}" -eq 1 ];then
     func_lib_disable_pulseaudio
 fi
 
-for idx in $(seq 1 $loop_cnt)
+for idx in $(seq 1 "$loop_cnt")
 do
     dlogi "===== Starting iteration $idx of $loop_cnt ====="
     ## - 1: remove module section

test-case/check-pause-resume.sh

@@ -46,7 +46,6 @@ OPT_NAME['S']='filter_string'   OPT_DESC['S']="run this case on specified pipeli
 OPT_HAS_ARG['S']=1             OPT_VAL['S']="id:any"
 
 func_opt_parse_option "$@"
-setup_kernel_check_point
 
 tplg=${OPT_VAL['t']}
 test_mode=${OPT_VAL['m']}

test-case/check-performance.sh

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

test-case/check-playback.sh

@@ -67,7 +67,6 @@ else
     dlogi "using $file as playback source"
 fi
 
-setup_kernel_check_point
 func_lib_check_sudo
 func_pipeline_export "$tplg" "type:playback & ${OPT_VAL['S']}"
 

test-case/check-selector-play.sh

@@ -128,7 +128,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-signal-stop-start.sh

@@ -60,12 +60,10 @@ case $test_mode in
     ;;
 esac
 
-setup_kernel_check_point
-
 func_stop_start_pipeline()
 {
     local i=1
-    while [ $i -le $count ]
+    while [ $i -le "$count" ]
     do
         # check aplay/arecord process state
         sof-process-state.sh "$pid" >/dev/null || {
@@ -76,10 +74,10 @@ func_stop_start_pipeline()
         dlogi "Stop/start count: $i"
         # stop the pipeline
         kill -SIGSTOP "$pid"
-        sleep $interval
+        sleep "$interval"
         # start the pipeline
         kill -SIGCONT "$pid"
-        sleep $interval
+        sleep "$interval"
         (( i++ ))
     done
 }

test-case/check-smart-amplifier.sh

@@ -60,7 +60,6 @@ start_test
 logger_disabled || func_lib_start_log_collect
 
 func_pipeline_export "$tplg" "smart_amp:any"
-setup_kernel_check_point
 
 [ "$PIPELINE_COUNT" == "2" ] || die "Only detect $PIPELINE_COUNT pipeline(s) from topology, but two are needed"
 
@@ -81,11 +80,11 @@ do
 done
 
 fmts="$cp_fmt"
-if [ ${OPT_VAL['F']} = '1' ]; then
+if [ "${OPT_VAL['F']}" = '1' ]; then
     fmts="$cp_fmts"
 fi
 
-for i in $(seq 1 $loop_cnt)
+for i in $(seq 1 "$loop_cnt")
 do
     for fmt in $fmts
     do

test-case/check-src-play.sh

@@ -113,7 +113,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-src-rec.sh

@@ -106,7 +106,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-suspend-resume-with-audio.sh

@@ -57,7 +57,6 @@ OPT_NAME['P']='pipelines'    OPT_DESC['P']="run test case on specified pipelines
 OPT_HAS_ARG['P']=1           OPT_VAL['P']="id:any"
 
 func_opt_parse_option "$@"
-setup_kernel_check_point
 func_lib_check_sudo
 
 tplg=${OPT_VAL['t']}
@@ -86,7 +85,7 @@ opt_arr=(-l "${OPT_VAL['l']}")
 if [ "${OPT_VAL['T']}" ]; then
     opt_arr+=(-T "${OPT_VAL['T']}")
 fi
-if [ ${OPT_VAL['r']} -eq 0  ]; then
+if [ "${OPT_VAL['r']}" -eq 0  ]; then
     opt_arr+=(-S "${OPT_VAL['S']}" -w "${OPT_VAL['w']}")
 else
     opt_arr+=(-r)
@@ -103,6 +102,7 @@ do
     fmt=$(func_pipeline_parse_value "$idx" fmt)
     dev=$(func_pipeline_parse_value "$idx" dev)
     snd=$(func_pipeline_parse_value "$idx" snd)
+    # shellcheck disable=SC2153
     dlogi "Run $TYPE command for the background"
     cmd_args="$cmd -D$dev -r $rate -c $channel -f $fmt $file_name -q"
     dlogc "$cmd_args"

test-case/check-userspace-cardinfo.sh

@@ -20,7 +20,6 @@ set -e
 source "$(dirname "${BASH_SOURCE[0]}")"/../case-lib/lib.sh
 
 func_opt_parse_option "$@"
-setup_kernel_check_point
 
 start_test