diff --git a/case-lib/config.sh b/case-lib/config.sh index f859f168..9c6ba288 100644 --- a/case-lib/config.sh +++ b/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 diff --git a/case-lib/lib.sh b/case-lib/lib.sh index de53bc2c..0b780843 100644 --- a/case-lib/lib.sh +++ b/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 diff --git a/test-case/check-capture.sh b/test-case/check-capture.sh index 2370cb3c..fb719fe3 100755 --- a/test-case/check-capture.sh +++ b/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 $? diff --git a/test-case/check-fw-echo-reference.sh b/test-case/check-fw-echo-reference.sh index ee9df0fa..d8459e2c 100755 --- a/test-case/check-fw-echo-reference.sh +++ b/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" diff --git a/test-case/check-ipc-flood.sh b/test-case/check-ipc-flood.sh index 0a1ec794..515917f7 100755 --- a/test-case/check-ipc-flood.sh +++ b/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 diff --git a/test-case/check-keyword-detection.sh b/test-case/check-keyword-detection.sh index fecfd6c8..96d79bef 100755 --- a/test-case/check-keyword-detection.sh +++ b/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" diff --git a/test-case/check-kmod-load-unload.sh b/test-case/check-kmod-load-unload.sh index fd3d683a..c006cfbd 100755 --- a/test-case/check-kmod-load-unload.sh +++ b/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" diff --git a/test-case/check-pause-release-suspend-resume.sh b/test-case/check-pause-release-suspend-resume.sh index 954301f7..561f5609 100755 --- a/test-case/check-pause-release-suspend-resume.sh +++ b/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 $? diff --git a/test-case/check-pause-resume.sh b/test-case/check-pause-resume.sh index 4daca33a..de0ebe92 100755 --- a/test-case/check-pause-resume.sh +++ b/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 $? diff --git a/test-case/check-playback.sh b/test-case/check-playback.sh index c05df2e8..9a2c91dc 100755 --- a/test-case/check-playback.sh +++ b/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" diff --git a/test-case/check-runtime-pm-double-active.sh b/test-case/check-runtime-pm-double-active.sh index 7d0f5453..4e2f861b 100755 --- a/test-case/check-runtime-pm-double-active.sh +++ b/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 $? diff --git a/test-case/check-runtime-pm-status.sh b/test-case/check-runtime-pm-status.sh index d959574f..3344dae7 100755 --- a/test-case/check-runtime-pm-status.sh +++ b/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 $? diff --git a/test-case/check-signal-stop-start.sh b/test-case/check-signal-stop-start.sh index a81c15a5..c3a0b6a0 100755 --- a/test-case/check-signal-stop-start.sh +++ b/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 $? diff --git a/test-case/check-smart-amplifier.sh b/test-case/check-smart-amplifier.sh index 214a3843..32e80bd2 100755 --- a/test-case/check-smart-amplifier.sh +++ b/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" diff --git a/test-case/check-suspend-resume-with-audio.sh b/test-case/check-suspend-resume-with-audio.sh index 5368f884..cc33e76c 100755 --- a/test-case/check-suspend-resume-with-audio.sh +++ b/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,12 +112,13 @@ 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" @@ -124,11 +126,7 @@ do 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 diff --git a/test-case/check-suspend-resume.sh b/test-case/check-suspend-resume.sh index d62f6a93..de5a8e15 100755 --- a/test-case/check-suspend-resume.sh +++ b/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,8 +74,8 @@ 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]} @@ -83,13 +83,11 @@ do 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 $? diff --git a/test-case/check-xrun-injection.sh b/test-case/check-xrun-injection.sh index 803c5670..da05e1d5 100755 --- a/test-case/check-xrun-injection.sh +++ b/test-case/check-xrun-injection.sh @@ -43,7 +43,7 @@ interval=${OPT_VALUE_lst['i']} [[ ${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 case $test_mode in @@ -122,5 +122,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 $? diff --git a/test-case/multiple-pause-resume.sh b/test-case/multiple-pause-resume.sh index 80407815..2427a0ee 100755 --- a/test-case/multiple-pause-resume.sh +++ b/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,7 +58,7 @@ func_pipeline_export $tplg "type:any" [[ ${OPT_VALUE_lst['s']} -eq 1 ]] && func_lib_start_log_collect -func_lib_setup_kernel_last_line +func_lib_setup_kernel_last_timestamp declare -a pipeline_idx_lst declare -a cmd_idx_lst @@ -91,7 +91,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 +145,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 timestamp for each iteration + func_lib_setup_kernel_last_timestamp for pipeline_combine_str in "${pipeline_combine_lst[@]}" do unset pid_lst @@ -165,7 +166,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 +188,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_LAST_TIMESTAMP || die "Catch error in kernel log" done -sof-kernel-log-check.sh $KERNEL_LAST_LINE -exit $? diff --git a/test-case/multiple-pipeline-capture.sh b/test-case/multiple-pipeline-capture.sh index 6ed9818d..a4ce93a2 100755 --- a/test-case/multiple-pipeline-capture.sh +++ b/test-case/multiple-pipeline-capture.sh @@ -51,7 +51,7 @@ 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_last_line +func_lib_setup_kernel_last_timestamp # now small function define declare -A APP_LST DEV_LST @@ -102,9 +102,9 @@ func_error_exit() for i in $(seq 1 $loop_cnt) do + # set up timestamp for each iteration + func_lib_setup_kernel_last_timestamp dlogi "===== Testing: (Loop: $i/$loop_cnt) =====" - # clean up dmesg - sudo dmesg -C # start capture: func_run_pipeline_with_type "capture" @@ -146,13 +146,11 @@ do sof-process-state.sh aplay >/dev/null [[ $? -eq 1 ]] && func_error_exit "Catch the abnormal process status of aplay" - # kill all arecord pkill -9 arecord 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_LAST_TIMESTAMP || die "Catch error in kernel log" done -sof-kernel-log-check.sh $KERNEL_LAST_LINE >/dev/null -exit $? diff --git a/test-case/multiple-pipeline-playback.sh b/test-case/multiple-pipeline-playback.sh index e0b97d6d..41048e42 100755 --- a/test-case/multiple-pipeline-playback.sh +++ b/test-case/multiple-pipeline-playback.sh @@ -51,7 +51,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_last_line # now small function define declare -A APP_LST DEV_LST @@ -102,6 +101,8 @@ func_error_exit() for i in $(seq 1 $loop_cnt) do + # set up timestamp for each iteration + func_lib_setup_kernel_last_timestamp dlogi "===== Testing: (Loop: $i/$loop_cnt) =====" # clean up dmesg sudo dmesg -C @@ -146,13 +147,11 @@ do sof-process-state.sh arecord >/dev/null [[ $? -eq 1 ]] && func_error_exit "Catch the abnormal process status of arecord" - # kill all arecord pkill -9 aplay pkill -9 arecord - 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 >/dev/null -exit $? diff --git a/test-case/simultaneous-playback-capture.sh b/test-case/simultaneous-playback-capture.sh index e50f515f..d1d3deeb 100755 --- a/test-case/simultaneous-playback-capture.sh +++ b/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_last_line func_error_exit() { @@ -69,6 +68,8 @@ func_error_exit() for i in $(seq 1 $loop_cnt) do + # set up timestamp for each iteration + func_lib_setup_kernel_last_timestamp dlogi "===== Testing: (Loop: $i/$loop_cnt) =====" # clean up dmesg sudo dmesg -C @@ -112,8 +113,7 @@ 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_LAST_TIMESTAMP || die "Catch error in kernel log" done -sof-kernel-log-check.sh $KERNEL_LAST_LINE > /dev/null -exit $? diff --git a/test-case/test-speaker.sh b/test-case/test-speaker.sh index 922a6149..e63cb9f6 100755 --- a/test-case/test-speaker.sh +++ b/test-case/test-speaker.sh @@ -32,7 +32,7 @@ tplg=${OPT_VALUE_lst['t']} func_pipeline_export $tplg "type:playback" tcnt=${OPT_VALUE_lst['l']} -func_lib_setup_kernel_last_line +func_lib_setup_kernel_last_timestamp for idx in $(seq 0 $(expr $PIPELINE_COUNT - 1)) do channel=$(func_pipeline_parse_value $idx channel) @@ -54,5 +54,5 @@ do fi done -sof-kernel-log-check.sh $KERNEL_LAST_LINE +sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP exit $? diff --git a/test-case/verify-sof-firmware-load.sh b/test-case/verify-sof-firmware-load.sh index 428159c1..ee0a8645 100755 --- a/test-case/verify-sof-firmware-load.sh +++ b/test-case/verify-sof-firmware-load.sh @@ -20,13 +20,14 @@ source "$(dirname "${BASH_SOURCE[0]}")"/../case-lib/lib.sh func_opt_parse_option "$@" -if ! alias | grep -q 'Sub-Test'; then - # 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;}') - cmd="sof-kernel-dump.sh" -else - cmd="journalctl --dmesg --no-pager" -fi +# 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;}' ) + +# flush and sync journalctl logs +sudo journalctl --sync --flush || true + +cmd="journalctl -k -q --no-pager --utc --output=short-monotonic --no-hostname" dlogi "Checking SOF Firmware load info in kernel log" if $cmd | grep -q " sof-audio.*Firmware.*version"; then @@ -36,12 +37,8 @@ if $cmd | grep -q " sof-audio.*Firmware.*version"; then $cmd | grep "Firmware debug build" -A3 | head -n 12 exit 0 else - printf ' ------\n debuging with /var/log/kern.log \n ---- \n' - ls -alht /var/log/kern.log - grep -na "Linux version" /var/log/kern.log || true - printf ' ------\n cmd was %s, DMESG_LOG_START_LINE was %s \n ---- \n' \ - "$cmd" "$DMESG_LOG_START_LINE" - journalctl --dmesg --lines 50 --no-pager - journalctl --dmesg | grep -C 1 " sof-audio.*Firmware.*version" || true + journalctl -k -q --no-pager --utc --output=short-monotonic --no-hostname --lines 50 || true + printf ' ------\n debugging with systemd journalctl \n ---- \n' + systemctl status systemd-journald* || true die "Cannot find the sof audio version" fi diff --git a/test-case/volume-basic-test.sh b/test-case/volume-basic-test.sh index c9983ced..f651baa9 100755 --- a/test-case/volume-basic-test.sh +++ b/test-case/volume-basic-test.sh @@ -62,7 +62,7 @@ dlogi "pgalist number = ${#pgalist[@]}" for i in $(seq 1 $maxloop) do - func_lib_setup_kernel_last_line + func_lib_setup_kernel_last_timestamp dlogi "===== Round($i/$maxloop) =====" # TODO: need to check command effect for i in "${pgalist[@]}" @@ -80,7 +80,7 @@ do sleep 1 dlogi "check dmesg for error" - sof-kernel-log-check.sh $KERNEL_LAST_LINE + sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP [[ $? -ne 0 ]] && func_error_exit "dmesg has errors!" done diff --git a/tools/sof-get-default-tplg.sh b/tools/sof-get-default-tplg.sh index 84c3bc2d..0b2e85e9 100755 --- a/tools/sof-get-default-tplg.sh +++ b/tools/sof-get-default-tplg.sh @@ -1,14 +1,12 @@ #!/bin/bash +# +# read kernel log to get topology file loaded by SOF driver +# Example from an apl up2 pcm512x device: +# +# sof-audio-pci 0000:00:0e.0: loading topology:intel/sof-tplg/sof-apl-pcm512x.tplg +# +# sof-apl-pcm512x.tplg will be returned +# -# Current: load TPLG file order: -# dmesg -# journalctl -# /var/log/syslog (sof-kernel-dump.sh) -# Future: possibly be loaded from elsewhere -# Notice: Only verified on Ubuntu 18.04 -tplg_file=$(dmesg |grep -i topology|awk -F ':' '/tplg/ {print $NF;}'|tail -n 1) -[[ ! "$tplg_file" ]] && \ - tplg_file=$(journalctl -k |grep -i topology |awk -F ':' '/tplg/ {print $NF;}'|tail -n 1) -[[ ! "$tplg_file" ]] && \ - tplg_file=$(sof-kernel-dump.sh |grep -i topology|awk -F ':' '/tplg/ {print $NF;}'|tail -n 1) +tplg_file=$(journalctl -k |grep -i topology |awk -F ':' '/tplg/ {print $NF;}'|tail -n 1) [[ "$tplg_file" ]] && basename $tplg_file || echo "" diff --git a/tools/sof-kernel-log-check.sh b/tools/sof-kernel-log-check.sh index 2fe11ae8..4ab57ee7 100755 --- a/tools/sof-kernel-log-check.sh +++ b/tools/sof-kernel-log-check.sh @@ -126,13 +126,10 @@ # Append some garbage to an ignore pattern to turn it off. Much easier # than deleting it. +begin_timestamp=${1:-0} +declare ignore_str -begin_line=${1:-1} -declare err_str ignore_str - -platform=$(sof-dump-status.py -p) - -err_str="error|failed|timed out|panic|oops" +platform=$($(dirname "$0")/sof-dump-status.py -p) # TODO explain # The first string cannot start by | @@ -241,32 +238,78 @@ case "$platform" in ;; esac -[[ ! "$err_str" ]] && echo "Missing error keyword list" && exit 0 -# dmesg KB size buffer size -#dmesg_config_define=$(awk -F '=' '/CONFIG_LOG_BUF_SHIFT/ {print $2;}' /boot/config-$(uname -r)) -#dmesg_buffer_size=$( echo $(( (1<<$dmesg_config_define) / 1024 )) ) -# kernel file log buffer size -#kernel_buffer_size=$(du -k /var/log/kern.log |awk '{print $1;}') -# now decide using which to catch the kernel log -#[[ $kernel_buffer_size -lt $dmesg ]] && cmd="dmesg" || cmd="tail -n +${begin_line} /var/log/kern.log" - -# confirm begin_line is number, if it is not the number, direct using dmesg -[[ "${begin_line//[0-9]/}" ]] && begin_line=0 -[[ "$begin_line" -eq 0 ]] && cmd="dmesg" || cmd="tail -n +${begin_line} /var/log/kern.log" - -#echo "run $0 with parameter '$*' for check kernel message error" - -# declare -p cmd -if [ "$ignore_str" ]; then - err=$( $cmd | grep 'Call Trace' -A5 -B3)$( $cmd | grep -E "$err_str"|grep -vE "$ignore_str") -else - err=$( $cmd | grep 'Call Trace' -A5 -B3)$( $cmd | grep -E "$err_str") -fi - -if [ "$err" ]; then - echo "$(date -u '+%Y-%m-%d %T %Z')" "[ERROR]" "Caught dmesg error" +# below are new error level kernel logs from journalctl --priority=err +# that did not influcen system and can be ignored + +# systemd issues can be ignored +# seen on mutiple platforms +# systemd[1]: Failed to mount Mount unit for core. +# systemd[1]: Failed to mount Mount unit for gnome-calculator. +# systemd[1]: Failed to mount Mount unit for [UNIT]. +ignore_str="$ignore_str"'|systemd\[.\]: Failed to mount Mount unit for' + +# initramfs issues can be ignored +ignore_str="$ignore_str"'|Initramfs unpacking failed' + +# keyboard issues can be ignored +ignore_str="$ignore_str"'|atkbd serio0: Failed to deactivate keyboard on isa0060/serio0' +ignore_str="$ignore_str"'|atkbd serio0: Failed to enable keyboard on isa0060/serio0' + +# smbus issues can be ignored +ignore_str="$ignore_str"'|i801_smbus 0000:00:..\..: Transaction timeout' +ignore_str="$ignore_str"'|i801_smbus 0000:00:..\..: Failed terminating the transaction' +ignore_str="$ignore_str""|i801_smbus 0000:00:..\..: SMBus is busy, can't use it!" +ignore_str="$ignore_str"'|i801_smbus 0000:00:..\..: Failed to allocate irq .: -16' + +# SATA related issue can be ignored is it did not break device +ignore_str="$ignore_str"'|ata3: COMRESET failed \(errno=-16\)' + +# genirq issues can be ignored +# origin logs seen on GLK platforms +# genirq: Flags mismatch irq 0. 00000080 (i801_smbus) vs. 00015a00 (timer) +ignore_str="$ignore_str"'|genirq: Flags mismatch irq .' + +# DMAR warnings can be ignored +# origin logs seen on BDW platforms +# DMAR: [Firmware Bug]: No firmware reserved region can cover this RMRR [0x00000000ad000000-0x00000000af7fffff], contact BIOS vendor for fixes +ignore_str="$ignore_str"'|DMAR: \[Firmware Bug\]: No firmware reserved region can cover this RMRR .' + +# dw_dmac logs can be ignored +# origin logs seen on BDW/BYT/CHT platforms +# dw_dmac INTL9C60:00: Missing DT data +# dw_dmac INTL9C60:01: Missing DT data +ignore_str="$ignore_str"'|dw_dmac INTL9C60:..: Missing DT data' + +# proc_thermal logs can be ignored +# origin logs seen on CHT platforms +# proc_thermal 0000:00:0b.0: No auxiliary DTSs enabled +ignore_str="$ignore_str"'|proc_thermal 0000:00:..\..: No auxiliary DTSs enabled' + +# touch pad logs can be ignored +# origin logs seen on GLK platforms +# elan_i2c i2c-ELAN0000:00: invalid report id data (ff) +ignore_str="$ignore_str"'|elan_i2c i2c-ELAN0000:.*: invalid report id data' + +# +# SDW related logs +# + +# origin logs seen on CML with RT700 platforms +# rt700 sdw:1:25d:700:0: Bus clash detected +ignore_str="$ignore_str"'|rt700 sdw:.:.*:700:.: Bus clash detected' + +# confirm begin_timestamp is in UNIX timestamp format, otherwise search full log +journalctlflag="-k -q --no-pager --utc --output=short-monotonic --no-hostname" +[[ $begin_timestamp =~ ^[0-9]{10} ]] && cmd="journalctl $journalctlflag --since=@$begin_timestamp" || cmd="journalctl $journalctlflag" + +declare -p cmd +# check priority err for error message +[[ "$ignore_str" ]] && err=$($cmd --priority=err | grep -vE "$ignore_str") || $($cmd --priority=err) + +[[ -z "$err" ]] || { + echo "$(date -u '+%Y-%m-%d %T %Z')" "[ERROR]" "Caught kernel log error" echo "===========================>>" echo "$err" echo "<<===========================" builtin exit 1 -fi +}