[RFC] use journalctl for kernel log

case-lib/config.sh

@@ -20,9 +20,9 @@ declare -A TPLG_IGNORE_LST
 TPLG_IGNORE_LST['pcm']='HDA Digital'
 
 # Will be set by the lib function, don't need to set
-# Catches the last line of /var/log/kern.log, which will be used by
-#   sof-kernel-log-check.
-# KERNEL_LAST_LINE
+# Catches the timestamp for a test case start used by
+# sof-kernel-log-check with journalctl
+# KERNEL_LAST_TIMESTAMP
 
 # If not set will be automatically set by logging_ctl function
 # Test case log root

case-lib/lib.sh

@@ -38,10 +38,10 @@ if [ ! "$SOFCARD" ]; then
     SOFCARD=$(grep 'sof-[a-z]' /proc/asound/cards|awk '{print $1;}')
 fi
 
-func_lib_setup_kernel_last_line()
+func_lib_setup_kernel_last_timestamp()
 {
     # shellcheck disable=SC2034 # external script will use it
-    KERNEL_LAST_LINE=$(wc -l /var/log/kern.log|awk '{print $1;}')
+    KERNEL_LAST_TIMESTAMP=$(date +%s)
 }
 
 # This function adds a fake error to dmesg (which is always saved by

test-case/check-capture.sh

@@ -59,7 +59,7 @@ file_prefix=${OPT_VALUE_lst['f']}
 
 [[ ${OPT_VALUE_lst['s']} -eq 1 ]] && func_lib_start_log_collect
 
-func_lib_setup_kernel_last_line
+func_lib_setup_kernel_last_timestamp
 func_lib_check_sudo
 func_pipeline_export $tplg "type:capture & ${OPT_VALUE_lst['S']}"
 
@@ -106,5 +106,5 @@ do
     done
 done
 
-sof-kernel-log-check.sh $KERNEL_LAST_LINE
+sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP
 exit $?

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

@@ -44,7 +44,7 @@ frequency=${OPT_VALUE_lst['f']}
 [[ ${OPT_VALUE_lst['s']} -eq 1 ]] && func_lib_start_log_collect
 
 func_pipeline_export $tplg "echo:any"
-func_lib_setup_kernel_last_line
+func_lib_setup_kernel_last_timestamp
 
 if [ "$PIPELINE_COUNT" != "2" ]; then
     die "Only detect $PIPELINE_COUNT pipeline(s) from topology, but two are needed"
@@ -93,4 +93,4 @@ do
     done
 done
 
-sof-kernel-log-check.sh "$KERNEL_LAST_LINE"
+sof-kernel-log-check.sh "$KERNEL_LAST_TIMESTAMP"

test-case/check-ipc-flood.sh

@@ -32,27 +32,27 @@ loop_cnt=${OPT_VALUE_lst['l']}
 
 [[ ! "$(sof-kernel-dump.sh|grep 'sof-audio'|grep 'Firmware debug build')" ]] && dlogw "${BASH_SOURCE[0]} need debug version firmware" && exit 2
 
-func_lib_setup_kernel_last_line
+func_lib_setup_kernel_last_timestamp
 func_lib_check_sudo
 
 dlogi "Check sof debug fs environment"
 [[ "$(sudo file $ipc_flood_dfs|grep 'No such file')" ]] && dlogw "${BASH_SOURCE[0]} need $ipc_flood_dfs to run the test case" && exit 2
 dlogi "Checking ipc flood test!"
 
-# cleanup dmesg buffer before test
-sudo dmesg -c > /dev/null
-
 for i in $(seq 1 $loop_cnt)
 do
+    # cleanup dmesg buffer for each iteration
+    sudo dmesg -c > /dev/null
+    # set up timestamp for each iteration
+    func_lib_setup_kernel_last_timestamp
     dlogi "===== [$i/$loop_cnt] loop Begin ====="
     dlogc "sudo bash -c 'echo $lpc_loop_cnt > $ipc_flood_dfs'"
     sudo bash -c "'echo $lpc_loop_cnt > $ipc_flood_dfs'"
 
-    sof-kernel-log-check.sh 0 || die "Catched error in dmesg"
+    # check kernel log for each iteration to catch issues
+    sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP || die "Catch error in kernel log"
 
     dlogi "Dumping test logs!"
     dmesg | grep "IPC Flood count" -A 2
-done
 
-sof-kernel-log-check.sh $KERNEL_LAST_LINE
-exit 0
+done

test-case/check-keyword-detection.sh

@@ -55,7 +55,7 @@ duration=${OPT_VALUE_lst['d']}
 [[ ${OPT_VALUE_lst['s']} -eq 1 ]] && func_lib_start_log_collect
 
 func_pipeline_export $tplg "kpbm:any"
-func_lib_setup_kernel_last_line
+func_lib_setup_kernel_last_timestamp
 
 if test "$PIPELINE_COUNT" != "1"; then
     die "detected $PIPELINE_COUNT wov pipeline(s) from topology, but 1 is needed"
@@ -154,4 +154,4 @@ do
     done
 done
 
-sof-kernel-log-check.sh "$KERNEL_LAST_LINE"
+sof-kernel-log-check.sh "$KERNEL_LAST_TIMESTAMP"

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

@@ -33,7 +33,7 @@ OPT_OPT_lst['p']='pulseaudio'   OPT_DESC_lst['p']='disable pulseaudio on the tes
 OPT_PARM_lst['p']=0             OPT_VALUE_lst['p']=1
 
 func_opt_parse_option "$@"
-func_lib_setup_kernel_last_line
+func_lib_setup_kernel_last_timestamp
 
 loop_cnt=${OPT_VALUE_lst['l']}
 
@@ -48,7 +48,7 @@ for idx in $(seq 1 $loop_cnt)
 do
     dlogi "===== Starting iteration $idx of $loop_cnt ====="
     ## - 1: remove module section
-    func_lib_setup_kernel_last_line
+    func_lib_setup_kernel_last_timestamp
 
     # After module removal, it takes about 10s for "aplay -l" to show
     # device list, within this 10s, it shows "no soundcard found". Here
@@ -75,10 +75,10 @@ do
 
     ## - 1a: check for errors after removal
     dlogi "checking for general errors after kmod unload with sof-kernel-log-check tool"
-    sof-kernel-log-check.sh "$KERNEL_LAST_LINE" ||
+    sof-kernel-log-check.sh "$KERNEL_LAST_TIMESTAMP" ||
         die "error found after kmod unload is real error, failing"
 
-    func_lib_setup_kernel_last_line
+    func_lib_setup_kernel_last_timestamp
     dlogi "run kmod/sof_insert.sh"
     sudo sof_insert.sh || {
         # FIXME: don't exit the status of dloge(). Use die()
@@ -87,7 +87,7 @@ do
 
     ## - 2a: check for errors after insertion
     dlogi "checking for general errors after kmod insert with sof-kernel-log-check tool"
-    sof-kernel-log-check.sh "$KERNEL_LAST_LINE" ||
+    sof-kernel-log-check.sh "$KERNEL_LAST_TIMESTAMP" ||
         die "Found error(s) in kernel log after module insertion"
 
     dlogi "checking if firmware is loaded successfully"

test-case/check-pause-release-suspend-resume.sh

@@ -110,7 +110,7 @@ esac
 
 [[ ${OPT_VALUE_lst['s']} -eq 1 ]] && func_lib_start_log_collect
 
-func_lib_setup_kernel_last_line
+func_lib_setup_kernel_last_timestamp
 
 dlogi "Entering audio stream expect script with: $cmd -D $pcm -r $rate -c $channel -f $fmt -vv -i $dummy_file -q"
 dlogi "Will enter suspend-resume cycle during paused period of audio stream process"
@@ -180,5 +180,5 @@ if [ $ret -ne 0 ]; then
     [[ $? -ne 0 ]] && dlogw "Kill process catch error"
     exit $ret
 fi
-sof-kernel-log-check.sh $KERNEL_LAST_LINE
+sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP
 exit $?

test-case/check-pause-resume.sh

@@ -75,9 +75,10 @@ esac
 [[ -z $file_name ]] && file_name=$dummy_file
 
 func_pipeline_export $tplg "type:$test_mode & ${OPT_VALUE_lst['S']}"
-func_lib_setup_kernel_last_line
 for idx in $(seq 0 $(expr $PIPELINE_COUNT - 1))
 do
+    # set up timestamp for each iteration
+    func_lib_setup_kernel_last_timestamp
     channel=$(func_pipeline_parse_value $idx channel)
     rate=$(func_pipeline_parse_value $idx rate)
     fmt=$(func_pipeline_parse_value $idx fmt)
@@ -122,9 +123,6 @@ END
         [[ $? -ne 0 ]] && dlogw "Kill process catch error"
         exit $ret
     fi
-    # sof-kernel-log-check script parameter number is 0/Non-Number will force check from dmesg
-    sof-kernel-log-check.sh 0 || die "Catch error in dmesg"
+    # check kernel log for each iteration to catch issues
+    sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP || die "Catch error in kernel log"
 done
-
-sof-kernel-log-check.sh $KERNEL_LAST_LINE
-exit $?

test-case/check-playback.sh

@@ -67,7 +67,7 @@ else
     dlogi "using $file as playback source"
 fi
 
-func_lib_setup_kernel_last_line
+func_lib_setup_kernel_last_timestamp
 func_lib_check_sudo
 func_pipeline_export $tplg "type:playback & ${OPT_VALUE_lst['S']}"
 
@@ -104,4 +104,4 @@ do
     done
 done
 
-sof-kernel-log-check.sh "$KERNEL_LAST_LINE"
+sof-kernel-log-check.sh "$KERNEL_LAST_TIMESTAMP"

test-case/check-runtime-pm-double-active.sh

@@ -71,7 +71,6 @@ DEV_LST['capture']='/dev/null'
 
 [[ ${OPT_VALUE_lst['s']} -eq 1 ]] && func_lib_start_log_collect
 func_pipeline_export $tplg "type:any"
-func_lib_setup_kernel_last_line
 
 for idx in $(seq 0 $(expr $PIPELINE_COUNT - 1))
 do
@@ -87,10 +86,10 @@ do
     dummy_file="${DEV_LST[$type]}"
     [[ -z $cmd ]] && dloge "$type is not supported, $cmd, $dummy_file" && exit 2
 
-    # clean up dmesg before the test
-    sudo dmesg -C
     for i in $(seq 1 $loop_count)
     do
+        # set up timestamp for each iteration
+        func_lib_setup_kernel_last_timestamp
         dlogi "===== Iteration $i of $loop_count for $pcm ====="
         # playback or capture device - check status
         dlogc "$cmd -D $dev -r $rate -c $channel -f $fmt $dummy_file -q"
@@ -136,10 +135,8 @@ do
             func_lib_lsof_error_dump $snd
             die "playback/capture failed on $pcm, $dev at $i/$loop_cnt."
         fi
+        # check kernel log for each iteration to catch issues
+        sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP || die "Catch error in kernel log"
     done
-
-    sof-kernel-log-check.sh 0 || die "Catch error in dmesg"
 done
 
-sof-kernel-log-check.sh $KERNEL_LAST_LINE
-exit $?

test-case/check-runtime-pm-status.sh

@@ -65,7 +65,6 @@ DEV_LST['capture']='/dev/null'
 
 [[ ${OPT_VALUE_lst['s']} -eq 1 ]] && func_lib_start_log_collect
 func_pipeline_export $tplg "type:any"
-func_lib_setup_kernel_last_line
 
 for idx in $(seq 0 $(expr $PIPELINE_COUNT - 1))
 do
@@ -83,6 +82,8 @@ do
 
     for i in $(seq 1 $loop_count)
     do
+        # set up timestamp for each iteration
+        func_lib_setup_kernel_last_timestamp
         dlogi "===== Iteration $i of $loop_count for $pcm ====="
         # playback or capture device - check status
         dlogc "$cmd -D $dev -r $rate -c $channel -f $fmt $dummy_file -q"
@@ -122,10 +123,8 @@ do
             func_lib_lsof_error_dump $snd
             exit 1
         fi
+        # check kernel log for each iteration to catch issues
+        sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP || die "Catch error in kernel log"
     done
-
-    sof-kernel-log-check.sh 0 || die "Catch error in dmesg"
 done
 
-sof-kernel-log-check.sh $KERNEL_LAST_LINE
-exit $?

test-case/check-signal-stop-start.sh

@@ -56,7 +56,7 @@ case $test_mode in
     ;;
 esac
 
-func_lib_setup_kernel_last_line
+func_lib_setup_kernel_last_timestamp
 
 func_stop_start_pipeline()
 {
@@ -116,5 +116,5 @@ do
     kill -9 $pid && wait $pid 2>/dev/null
 done
 
-sof-kernel-log-check.sh $KERNEL_LAST_LINE
+sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP
 exit $?

test-case/check-smart-amplifier.sh

@@ -59,7 +59,7 @@ tplg=${OPT_VALUE_lst['t']}
 [[ ${OPT_VALUE_lst['s']} -eq 1 ]] && func_lib_start_log_collect
 
 func_pipeline_export $tplg "smart_amp:any"
-func_lib_setup_kernel_last_line
+func_lib_setup_kernel_last_timestamp
 
 [ "$PIPELINE_COUNT" == "2" ] || die "Only detect $PIPELINE_COUNT pipeline(s) from topology, but two are needed"
 
@@ -114,4 +114,4 @@ do
     done
 done
 
-sof-kernel-log-check.sh "$KERNEL_LAST_LINE"
+sof-kernel-log-check.sh "$KERNEL_LAST_TIMESTAMP"

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

@@ -53,7 +53,6 @@ OPT_PARM_lst['f']=1         OPT_VALUE_lst['f']=''
 
 func_opt_parse_option "$@"
 func_lib_check_sudo
-func_lib_setup_kernel_last_line
 
 tplg=${OPT_VALUE_lst['t']}
 [[ ${OPT_VALUE_lst['s']} -eq 1 ]] && func_lib_start_log_collect
@@ -88,6 +87,8 @@ fi
 
 for idx in $(seq 0 $(expr $PIPELINE_COUNT - 1))
 do
+    # set up timestamp for each iteration
+    func_lib_setup_kernel_last_timestamp
     channel=$(func_pipeline_parse_value $idx channel)
     rate=$(func_pipeline_parse_value $idx rate)
     fmt=$(func_pipeline_parse_value $idx fmt)
@@ -111,24 +112,21 @@ do
         ps --ppid $$ -f
         exit 1
     fi
-    $(dirname ${BASH_SOURCE[0]})/check-suspend-resume.sh $(echo $opt)
-    ret=$?
-    [[ $ret -ne 0 ]] && dloge "suspend resume failed" && exit $ret
+    $(dirname ${BASH_SOURCE[0]})/check-suspend-resume.sh $(echo $opt) || die "suspend resume failed"
+
+    # check kernel log for each iteration to catch issues
+    sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP || die "Catch error in kernel log"
+
     # check process status is correct
-    sof-process-state.sh $process_id
-    if [ $? -ne 0 ]; then
+    sof-process-state.sh $process_id || {
         func_lib_lsof_error_dump $snd
         dloge "process status is abnormal"
         dlogi "dump ps for aplay & arecord"
         ps -ef |grep -E 'aplay|arecord'
         dlogi "dump ps for child process"
         ps --ppid $$ -f
         exit 1
-    fi
+    }
     dlogi "Killing $cmd_args"
-    kill -9 $process_id
-    sof-kernel-log-check.sh 0 || die "Catch error in dmesg"
+    kill -9 $process_id || true
 done
-
-# check full log
-sof-kernel-log-check.sh $KERNEL_LAST_LINE

test-case/check-suspend-resume.sh

@@ -41,7 +41,7 @@ OPT_PARM_lst['r']=0         OPT_VALUE_lst['r']=0
 
 func_opt_parse_option "$@"
 func_lib_check_sudo
-func_lib_setup_kernel_last_line
+func_lib_setup_kernel_last_timestamp
 
 type=${OPT_VALUE_lst['T']}
 # switch type
@@ -74,22 +74,20 @@ fi
 for i in $(seq 1 $loop_count)
 do
     dlogi "===== Round($i/$loop_count) ====="
-    # cleanup dmesg befor run case
-    sudo dmesg --clear
+    # set up timestamp for each iteration
+    func_lib_setup_kernel_last_timestamp
     sleep_count=$(cat /sys/power/wakeup_count)
     dlogc "Run the command: rtcwake -m mem -s ${sleep_lst[$i]}"
     sudo rtcwake -m mem -s ${sleep_lst[$i]}
     [[ $? -ne 0 ]] && die "rtcwake return value error"
     dlogc "sleep for ${wait_lst[$i]}"
     sleep ${wait_lst[$i]}
     dlogi "Check for the kernel log status"
-    wake_count=$(cat /sys/power/wakeup_count)
-    # sof-kernel-log-check script parameter number is 0/Non-Number will force check from dmesg
-    sof-kernel-log-check.sh 0 || die "Catch error in dmesg"
+    # check kernel log for each iteration to catch issues
+    sof-kernel-log-check.sh "$KERNEL_LAST_TIMESTAMP" || die "Catch error in kernel log"
     # check wakeup count correct
-    [[ $wake_count -le $sleep_count ]] && die "suspend/resume didn't happen, because /sys/power/wakeup_count does not increase"
+    wake_count=$(cat /sys/power/wakeup_count)
+    dlogi "Check for the wakeup_count"
+    [[ $wake_count -gt $sleep_count ]] || die "suspend/resume didn't happen, because /sys/power/wakeup_count does not increase"
 done
 
-# check full log
-sof-kernel-log-check.sh $KERNEL_LAST_LINE
-exit $?