sof-test: use journalctl for log collection

case-lib/hijack.sh

@@ -50,17 +50,14 @@ function func_exit_handler()
         wcLog=$(wc -l "$logfile")
         dlogi "nlines=$wcLog"
     fi
-    # when case ends, store kernel log
-    # /var/log/kern.log format:
-    # f1    f2  f3   f4          f5      f6 f7    f8...
-    # Mouth day Time MachineName kernel: [  time] content
-    # May 15 21:28:38 MachineName kernel: [    6.469255] sof-audio-pci 0000:00:0e.0: ipc rx: 0x90020000: GLB_TRACE_MSG
-    # May 15 21:28:38 MachineName kernel: [    6.469268] sof-audio-pci 0000:00:0e.0: ipc rx done: 0x90020000: GLB_TRACE_MSG
-    if [[ -n "$DMESG_LOG_START_LINE" && "$DMESG_LOG_START_LINE" -ne 0 ]]; then
-        tail -n +"$DMESG_LOG_START_LINE" /var/log/kern.log |cut -f5- -d ' ' > "$LOG_ROOT/dmesg.txt"
+
+    if [[ "$KERNEL_CHECKPOINT" =~ ^[0-9]{10} ]]; then
+        journalctl_cmd --since=@"$KERNEL_CHECKPOINT" > "$LOG_ROOT/dmesg.txt"
     else
-        cut -f5- -d ' ' /var/log/kern.log > "$LOG_ROOT/dmesg.txt"
+        die 'Kernel check point "KERNEL_CHECKPOINT" is not properly set'
     fi
+    # After log collected, KERNEL_CHECKPOINT will not be used any more
+    unset KERNEL_CHECKPOINT
 
     # get ps command result as list
     local -a cmd_lst

case-lib/lib.sh

@@ -327,13 +327,6 @@ die()
     exit 1
 }
 
-# force ask buffer data write into file system
-sudo sync -f || true
-# catch kern.log last line as current case start line
-if [ ! "$DMESG_LOG_START_LINE" ]; then
-    DMESG_LOG_START_LINE=$(wc -l /var/log/kern.log|awk '{print $1;}')
-fi
-
 is_sof_used()
 {
     grep -q "sof" /proc/asound/cards;

test-case/check-alsabat.sh

@@ -43,6 +43,7 @@ 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-ipc-flood.sh

@@ -25,6 +25,7 @@ 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']}

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

@@ -66,6 +66,8 @@ fi
 
 for counter in $(seq 1 $loop_cnt)
 do
+    # Only collect the latest success/failure logs
+    setup_kernel_check_point
     dlogi "===== Starting iteration $counter of $loop_cnt ====="
 
     # logic: if this case disables pulseaudio, the sub case does not need to disable pulseaudio

test-case/check-pause-resume.sh

@@ -45,6 +45,7 @@ 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-reboot.sh

@@ -150,7 +150,7 @@ $old_content
 
 $boot_once_flag
 export LOG_ROOT='$(realpath $LOG_ROOT)'
-export DMESG_LOG_START_LINE=$(wc -l /var/log/kern.log|awk '{print $1;}')
+setup_kernel_check_point
 bash -c '$full_cmd'
 
 exit 0

test-case/check-sof-logger.sh

@@ -22,8 +22,7 @@ func_opt_parse_option "$@"
 
 #TODO: need to add arguments for user to give location for logger and ldc file
 
-# hijack DMESG_LOG_START_LINE which refer dump kernel log in exit function
-DMESG_LOG_START_LINE=$(sof-get-kernel-line.sh|tail -n 1 |awk '{print $1;}')
+setup_kernel_check_point
 
 # check sof-logger location
 if [ -z $(which sof-logger) ]; then

test-case/check-suspend-resume-with-audio.sh

@@ -55,6 +55,7 @@ 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']}

test-case/check-userspace-cardinfo.sh

@@ -23,6 +23,7 @@ source "$(dirname "${BASH_SOURCE[0]}")"/../case-lib/lib.sh
 func_lib_check_pa || die "Please check whether pulseaudio runs correctly or not"
 
 func_opt_parse_option "$@"
+setup_kernel_check_point
 
 : $((available_card=0))
 while read -r card; do

test-case/check-userspace-paplay.sh

@@ -42,6 +42,7 @@ OPT_NAME['C']='channels'   OPT_DESC['C']='channels'
 OPT_HAS_ARG['C']=1         OPT_VAL['C']=2
 
 func_opt_parse_option "$@"
+setup_kernel_check_point
 
 round_cnt=${OPT_VAL['r']}
 duration=${OPT_VAL['d']}

test-case/check-userspace-parecord.sh

@@ -42,6 +42,7 @@ OPT_NAME['C']='channels'   OPT_DESC['C']='channels'
 OPT_HAS_ARG['C']=1         OPT_VAL['C']=2
 
 func_opt_parse_option "$@"
+setup_kernel_check_point
 
 round_cnt=${OPT_VAL['r']}
 duration=${OPT_VAL['d']}

test-case/simultaneous-playback-capture.sh

@@ -33,6 +33,8 @@ 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
+
 tplg=${OPT_VAL['t']}
 wait_time=${OPT_VAL['w']}
 loop_cnt=${OPT_VAL['l']}

test-case/verify-bootsequence.sh

@@ -30,6 +30,7 @@ ALSALIB_VER=1.2.2-44
 ALSAUCM_VER=1.2.3-15
 
 func_opt_parse_option "$@"
+setup_kernel_check_point
 
 main()
 {

test-case/verify-firmware-presence.sh

@@ -20,6 +20,7 @@ set -e
 source "$(dirname "${BASH_SOURCE[0]}")"/../case-lib/lib.sh
 
 func_opt_parse_option "$@"
+setup_kernel_check_point
 
 path=$(sof-dump-status.py -P)
 platform=$(sof-dump-status.py -p)

test-case/verify-kernel-module-load-probe.sh

@@ -17,8 +17,7 @@ source $(dirname ${BASH_SOURCE[0]})/../case-lib/lib.sh
 
 func_opt_parse_option "$@"
 
-# hijack DMESG_LOG_START_LINE which refer dump kernel log in exit function
-DMESG_LOG_START_LINE=$(sof-get-kernel-line.sh|tail -n 1 |awk '{print $1;}')
+setup_kernel_check_point
 
 dlogi "Checking if sof relative modules loaded"
 dlogc "lsmod | grep \"sof\""

test-case/verify-pcm-list.sh

@@ -29,9 +29,7 @@ tplg=${OPT_VAL['t']}
 tplg_path=$(func_lib_get_tplg_path "$tplg") ||
        	die "No available topology for this test case"
 
-# hijack DMESG_LOG_START_LINE which refer dump kernel log in exit function
-DMESG_LOG_START_LINE=$(sof-get-kernel-line.sh|tail -n 1 |awk '{print $1;}')
-
+setup_kernel_check_point
 
 tplg_str=$(sof-tplgreader.py "$tplg_path" -d id pcm type -o)
 pcm_str=$(sof-dump-status.py -i "${SOFCARD:-0}")

test-case/verify-sof-firmware-load.sh

@@ -20,9 +20,7 @@ source "$(dirname "${BASH_SOURCE[0]}")"/../case-lib/lib.sh
 
 func_opt_parse_option "$@"
 
-# hijack DMESG_LOG_START_LINE to dump kernel from file start is not Sub-Test
-# TODO: clean up Sub-Test feature
-alias | grep -q 'Sub-Test' || DMESG_LOG_START_LINE=$(sof-get-kernel-line.sh | tail -n 1 | awk '{print $1;}' )
+setup_kernel_check_point
 
 cmd="journalctl_cmd"
 

test-case/verify-tplg-binary.sh

@@ -23,6 +23,7 @@ OPT_NAME['t']='tplg'     OPT_DESC['t']='tplg file, default value is env TPLG: $'
 OPT_HAS_ARG['t']=1         OPT_VAL['t']="$TPLG"
 
 func_opt_parse_option "$@"
+setup_kernel_check_point
 tplg=${OPT_VAL['t']}
 
 tplg_path=`func_lib_get_tplg_path "$tplg"`

test-case/verify-ucm-config.sh

@@ -25,6 +25,7 @@
 source $(dirname ${BASH_SOURCE[0]})/../case-lib/lib.sh
 
 func_opt_parse_option "$@"
+setup_kernel_check_point
 
 declare -A verb_array
 

test-case/volume-basic-test.sh

@@ -28,6 +28,7 @@ OPT_NAME['s']='sof-logger'   OPT_DESC['s']="Open sof-logger trace the data will
 OPT_HAS_ARG['s']=0             OPT_VAL['s']=1
 
 func_opt_parse_option "$@"
+setup_kernel_check_point
 tplg=${OPT_VAL['t']}
 maxloop=${OPT_VAL['l']}
 

tools/sof-kernel-log-check.sh

@@ -135,6 +135,10 @@ platform=$("$test_dir"/tools/sof-dump-status.py -p)
 
 # shellcheck source=case-lib/lib.sh
 source "$test_dir"/case-lib/lib.sh
+# The lib.sh sourced hijack.sh, which trapped exit to use our
+# exit handler, because this is not a test case, we don't need
+# the exit handler.
+trap - EXIT
 
 # The first string cannot start by |