journalctl patchset version 5

case-lib/lib.sh

@@ -41,7 +41,7 @@ fi
 func_lib_setup_kernel_checkpoint()
 {
     # shellcheck disable=SC2034 # external script will use it
-    KERNEL_CHECKPOINT=$(wc -l /var/log/kern.log|awk '{print $1;}')
+    KERNEL_CHECKPOINT=$(date +%s)
 }
 
 # This function adds a fake error to dmesg (which is always saved by
@@ -311,3 +311,10 @@ is_sof_used()
 {
     grep -q "sof" /proc/asound/cards;
 }
+
+# a wrapper to journalctl with required style
+journalctl_cmd()
+{
+   journalctl -k -q --no-pager --utc --output=short-monotonic \
+     --no-hostname  "$@"
+}

test-case/check-ipc-flood.sh

@@ -32,27 +32,26 @@ 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_checkpoint
 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
+    # TODO: use journalctl to replace dmesg
+    # cleanup dmesg buffer for each iteration
+    sudo dmesg -c > /dev/null
+    # set up timestamp for each iteration
+    func_lib_setup_kernel_checkpoint
     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 "Caught error in dmesg"
-
+    # check kernel log for each iteration to catch issues
+    sof-kernel-log-check.sh "$KERNEL_CHECKPOINT" || die "Caught error in kernel log"
+    # TODO: use journalctl to replace dmesg
     dlogi "Dumping test logs!"
     dmesg | grep "IPC Flood count" -A 2
 done
-
-sof-kernel-log-check.sh "$KERNEL_CHECKPOINT"
-exit 0

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_checkpoint
 for idx in $(seq 0 $(expr $PIPELINE_COUNT - 1))
 do
+    # set up checkpoint for each iteration
+    func_lib_setup_kernel_checkpoint
     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_CHECKPOINT" || die "Caught error in kernel log"
 done
-
-sof-kernel-log-check.sh "$KERNEL_CHECKPOINT"
-exit $?

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_checkpoint
 
 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 checkpoint for each iteration
+        func_lib_setup_kernel_checkpoint
         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,7 @@ 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_CHECKPOINT" || die "Caught error in kernel log"
     done
-
-    sof-kernel-log-check.sh 0 || die "Catch error in dmesg"
 done
-
-sof-kernel-log-check.sh "$KERNEL_CHECKPOINT"
-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_checkpoint
 
 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 checkpoint for each iteration
+        func_lib_setup_kernel_checkpoint
         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,7 @@ 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_CHECKPOINT" || die "Caught error in kernel log"
     done
-
-    sof-kernel-log-check.sh 0 || die "Catch error in dmesg"
 done
-
-sof-kernel-log-check.sh "$KERNEL_CHECKPOINT"
-exit $?

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_checkpoint
 
 tplg=${OPT_VALUE_lst['t']}
 [[ ${OPT_VALUE_lst['s']} -eq 1 ]] && func_lib_start_log_collect
@@ -88,6 +87,10 @@ fi
 
 for idx in $(seq 0 $(expr $PIPELINE_COUNT - 1))
 do
+    # set up checkpoint for each iteration
+    func_lib_setup_kernel_checkpoint
+    # store local checkpoint as we have sub-test
+    LOCAL_CHECK_POINT="$KERNEL_CHECKPOINT"
     channel=$(func_pipeline_parse_value $idx channel)
     rate=$(func_pipeline_parse_value $idx rate)
     fmt=$(func_pipeline_parse_value $idx fmt)
@@ -111,24 +114,22 @@ 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 "$LOCAL_CHECK_POINT" || die "Caught 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_CHECKPOINT"

test-case/check-suspend-resume.sh

@@ -41,7 +41,6 @@ OPT_PARM_lst['r']=0         OPT_VALUE_lst['r']=0
 
 func_opt_parse_option "$@"
 func_lib_check_sudo
-func_lib_setup_kernel_checkpoint
 
 type=${OPT_VALUE_lst['T']}
 # switch type
@@ -74,22 +73,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 checkpoint for each iteration
+    func_lib_setup_kernel_checkpoint
     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_CHECKPOINT" || die "Caught 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 -ge $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_CHECKPOINT"
-exit $?

test-case/multiple-pause-resume.sh

@@ -12,7 +12,7 @@ set -e
 ##    expect sleep for sleep time then mocks spacebar keypresses ' ' to
 ##    cause resume action
 ## Case step:
-##    1. run 1st pipeline 
+##    1. run 1st pipeline
 ##    2. pickup any other pipeline
 ##    3. use expect to fake pause/resume in each pipeline
 ##    4. go through with tplg file
@@ -58,8 +58,6 @@ func_pipeline_export "$tplg" "type:any"
 
 [[ ${OPT_VALUE_lst['s']} -eq 1 ]] && func_lib_start_log_collect
 
-func_lib_setup_kernel_checkpoint
-
 declare -a pipeline_idx_lst
 declare -a cmd_idx_lst
 declare -a file_idx_lst
@@ -91,7 +89,7 @@ done
 [[ ${#pipeline_idx_lst[*]} -gt ${OPT_VALUE_lst['c']} ]] && max_count=${OPT_VALUE_lst['c']} || max_count=${#pipeline_idx_lst[*]}
 [[ $max_count -eq 1 ]] && dlogw "pipeline count is 1, don't need to run this case" && exit 2
 
-# create combination list 
+# create combination list
 declare -a pipeline_combine_lst
 for i in $(sof-combinatoric.py -n ${#pipeline_idx_lst[*]} -p $max_count)
 do
@@ -145,7 +143,8 @@ max_wait_time=$[ 10 * $repeat_count ]
 for i in $(seq 1 $loop_count)
 do
     dlogi "===== Loop count( $i / $loop_count ) ====="
-    sudo dmesg -c >/dev/null
+    # set up checkpoint for each iteration
+    func_lib_setup_kernel_checkpoint
     for pipeline_combine_str in "${pipeline_combine_lst[@]}"
     do
         unset pid_lst
@@ -165,7 +164,7 @@ do
             [[ ! "$(pidof expect)" ]] && break
         done
         # fix aplay/arecord last output
-        echo 
+        echo
         if [ "$(pidof expect)" ]; then
             dloge "Still have expect process not finished after wait for $max_wait_time"
             # now dump process
@@ -187,8 +186,7 @@ do
             [[ $? -ne 0 ]] && die "pause resume is exit status error"
         done
     done
-    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_CHECKPOINT" || die "Caught error in kernel log"
 done
 
-sof-kernel-log-check.sh "$KERNEL_CHECKPOINT"
-exit $?

test-case/multiple-pipeline-capture.sh

@@ -56,7 +56,6 @@ max_count=0
 func_pipeline_export "$tplg" "type:any" # this line will help to get $PIPELINE_COUNT
 # get the min value of TPLG:'pipeline count' with Case:'pipeline count'
 [[ $PIPELINE_COUNT -gt ${OPT_VALUE_lst['c']} ]] && max_count=${OPT_VALUE_lst['c']} || max_count=$PIPELINE_COUNT
-func_lib_setup_kernel_checkpoint
 
 # now small function define
 declare -A APP_LST DEV_LST
@@ -110,9 +109,9 @@ func_error_exit()
 
 for i in $(seq 1 $loop_cnt)
 do
+    # set up checkpoint for each iteration
+    func_lib_setup_kernel_checkpoint
     dlogi "===== Testing: (Loop: $i/$loop_cnt) ====="
-    # clean up dmesg
-    sudo dmesg -C
 
     # start capture:
     func_run_pipeline_with_type "capture"
@@ -154,13 +153,11 @@ do
     [ "$play_count" = 0 ] || sof-process-state.sh aplay >/dev/null ||
         func_error_exit "Catch the abnormal process status of aplay"
 
-
     dlogc 'pkill -9 aplay arecord'
     [ "$rec_count" = 0 ] || pkill -9 arecord
     [ "$play_count" = 0 ] || pkill -9 aplay
 
-    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_CHECKPOINT" || die "Caught error in kernel log"
 done
 
-sof-kernel-log-check.sh "$KERNEL_CHECKPOINT" >/dev/null
-exit $?

test-case/multiple-pipeline-playback.sh

@@ -56,7 +56,6 @@ max_count=0
 func_pipeline_export "$tplg" "type:any" # this line will help to get $PIPELINE_COUNT
 # get the min value of TPLG:'pipeline count' with Case:'pipeline count'
 [[ $PIPELINE_COUNT -gt ${OPT_VALUE_lst['c']} ]] && max_count=${OPT_VALUE_lst['c']} || max_count=$PIPELINE_COUNT
-func_lib_setup_kernel_checkpoint
 
 # now small function define
 declare -A APP_LST DEV_LST
@@ -108,6 +107,8 @@ func_error_exit()
 
 for i in $(seq 1 $loop_cnt)
 do
+    # set up checkpoint for each iteration
+    func_lib_setup_kernel_checkpoint
     dlogi "===== Testing: (Loop: $i/$loop_cnt) ====="
     # clean up dmesg
     sudo dmesg -C
@@ -157,7 +158,6 @@ do
     [ "$rec_count" = 0 ] || pkill -9 arecord
     [ "$play_count" = 0 ] || pkill -9 aplay
 
-    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_CHECKPOINT" || die "Caught error in kernel log"
 done
-
-sof-kernel-log-check.sh "$KERNEL_CHECKPOINT" >/dev/null

test-case/simultaneous-playback-capture.sh

@@ -57,7 +57,6 @@ id_lst_str=${id_lst_str/,/} # remove 1st, which is not used
 [[ ${#id_lst_str} -eq 0 ]] && dlogw "no pipeline with both playback and capture capabilities found in $tplg" && exit 2
 func_pipeline_export "$tplg" "id:$id_lst_str"
 [[ ${OPT_VALUE_lst['s']} -eq 1 ]] && func_lib_start_log_collect
-func_lib_setup_kernel_checkpoint
 
 func_error_exit()
 {
@@ -69,9 +68,9 @@ func_error_exit()
 
 for i in $(seq 1 $loop_cnt)
 do
+    # set up checkpoint for each iteration
+    func_lib_setup_kernel_checkpoint
     dlogi "===== Testing: (Loop: $i/$loop_cnt) ====="
-    # clean up dmesg
-    sudo dmesg -C
     # following sof-tplgreader, split 'both' pipelines into separate playback & capture pipelines, with playback occurring first
     for order in $(seq 0 2 $(expr $PIPELINE_COUNT - 1))
     do
@@ -112,8 +111,6 @@ do
         kill -9 $arecord_pid && wait $arecord_pid 2>/dev/null
 
     done
-    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_CHECKPOINT" || die "Caught error in kernel log"
 done
-
-sof-kernel-log-check.sh "$KERNEL_CHECKPOINT" > /dev/null
-exit $?