From b47bce6b43e92b53656cb37be5c7abcc5e8a7347 Mon Sep 17 00:00:00 2001 From: Pan Xiuli Date: Wed, 28 Oct 2020 05:33:06 +0000 Subject: [PATCH 01/16] test-case: check-pause-resume: check kernel log in each iteration remove the redundant kernel log check for all case. enable kernel log check for each iteration. Signed-off-by: Pan Xiuli --- test-case/check-pause-resume.sh | 10 ++++------ 1 file changed, 4 insertions(+), 6 deletions(-) diff --git a/test-case/check-pause-resume.sh b/test-case/check-pause-resume.sh index 8cedd820..d4567eb5 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_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 $? From 76a72bbe66d3ea2154552dfe81bec966dd9bcb69 Mon Sep 17 00:00:00 2001 From: Pan Xiuli Date: Wed, 28 Oct 2020 05:43:32 +0000 Subject: [PATCH 02/16] test-case: check-runtime-pm-status: check kernel log in each iteration remove the redundant kernel log check for all case. enable kernel log check for each iteration. Signed-off-by: Pan Xiuli --- test-case/check-runtime-pm-status.sh | 10 ++++------ 1 file changed, 4 insertions(+), 6 deletions(-) diff --git a/test-case/check-runtime-pm-status.sh b/test-case/check-runtime-pm-status.sh index ee8e0df5..d5fefff7 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_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 $? From 42ccfa1d4d9eb7f7c78c549865975b9283269a51 Mon Sep 17 00:00:00 2001 From: Pan Xiuli Date: Wed, 28 Oct 2020 05:50:24 +0000 Subject: [PATCH 03/16] test-case: check-ipc-flood: check kernel log in each iteration remove the redundant kernel log check for all case. enable kernel log check for each iteration. Signed-off-by: Pan Xiuli --- test-case/check-ipc-flood.sh | 17 ++++++++--------- 1 file changed, 8 insertions(+), 9 deletions(-) diff --git a/test-case/check-ipc-flood.sh b/test-case/check-ipc-flood.sh index c9af7280..8ab582c1 100755 --- a/test-case/check-ipc-flood.sh +++ b/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 From 58d6d161d9231ae2e0eb324f15a4622fa35b49cd Mon Sep 17 00:00:00 2001 From: Pan Xiuli Date: Wed, 28 Oct 2020 05:54:43 +0000 Subject: [PATCH 04/16] test-case: check-suspend-resume: check kernel log in each iteration remove the redundant kernel log check for all case. enable kernel log check for each iteration. Signed-off-by: Pan Xiuli --- test-case/check-suspend-resume.sh | 17 +++++++---------- 1 file changed, 7 insertions(+), 10 deletions(-) diff --git a/test-case/check-suspend-resume.sh b/test-case/check-suspend-resume.sh index 578273e6..50f04817 100755 --- a/test-case/check-suspend-resume.sh +++ b/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,8 +73,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 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]} @@ -83,13 +82,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_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 $? From f17d12e6084ddbabfb5ba17fe12c35b0ec79e118 Mon Sep 17 00:00:00 2001 From: Pan Xiuli Date: Wed, 28 Oct 2020 05:58:24 +0000 Subject: [PATCH 05/16] test-case: check-suspend-resume-with-audio: check kernel log in each iteration remove the redundant kernel log check for all case. enable kernel log check for each iteration. also do some clean up for this script Signed-off-by: Pan Xiuli --- test-case/check-suspend-resume-with-audio.sh | 23 ++++++++++---------- 1 file changed, 12 insertions(+), 11 deletions(-) diff --git a/test-case/check-suspend-resume-with-audio.sh b/test-case/check-suspend-resume-with-audio.sh index 12ce8015..65eddab0 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_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,12 +114,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 "$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" @@ -124,11 +128,8 @@ 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_CHECKPOINT" From 40caea499be93c82306cbde54191f04297c80854 Mon Sep 17 00:00:00 2001 From: Pan Xiuli Date: Wed, 28 Oct 2020 06:04:59 +0000 Subject: [PATCH 06/16] test-case: check-runtime-pm-double-active: check kernel log in each iteration remove the redundant kernel log check for all case. enable kernel log check for each iteration. Signed-off-by: Pan Xiuli --- test-case/check-runtime-pm-double-active.sh | 12 ++++-------- 1 file changed, 4 insertions(+), 8 deletions(-) diff --git a/test-case/check-runtime-pm-double-active.sh b/test-case/check-runtime-pm-double-active.sh index ded8f7cd..af0c29bb 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_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 $? From 0780ee6787a8357ac947799aa3a7445f2d98d60f Mon Sep 17 00:00:00 2001 From: Pan Xiuli Date: Wed, 28 Oct 2020 06:06:21 +0000 Subject: [PATCH 07/16] test-case: multiple-pause-resume: check kernel log in each iteration remove the redundant kernel log check for all case. enable kernel log check for each iteration. Signed-off-by: Pan Xiuli --- test-case/multiple-pause-resume.sh | 16 +++++++--------- 1 file changed, 7 insertions(+), 9 deletions(-) diff --git a/test-case/multiple-pause-resume.sh b/test-case/multiple-pause-resume.sh index bf03a89f..d2cd8d66 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,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 $? From 4be4e2040d80bd2871b7fe8f13a83566d1a38d8d Mon Sep 17 00:00:00 2001 From: Pan Xiuli Date: Wed, 28 Oct 2020 05:45:58 +0000 Subject: [PATCH 08/16] test-case: multiple-pipeline-playback: check kernel log in each iteration remove the redundant kernel log check for all case. enable kernel log check for each iteration. Signed-off-by: Pan Xiuli --- test-case/multiple-pipeline-playback.sh | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/test-case/multiple-pipeline-playback.sh b/test-case/multiple-pipeline-playback.sh index 44f7170a..76d24d40 100755 --- a/test-case/multiple-pipeline-playback.sh +++ b/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 From 35046b739ec9c17fedc345c380489a50144c084f Mon Sep 17 00:00:00 2001 From: Pan Xiuli Date: Wed, 28 Oct 2020 05:53:02 +0000 Subject: [PATCH 09/16] test-case: multiple-pipeline-capture: check kernel log in each iteration remove the redundant kernel log check for all case. enable kernel log check for each iteration. Signed-off-by: Pan Xiuli --- test-case/multiple-pipeline-capture.sh | 11 ++++------- 1 file changed, 4 insertions(+), 7 deletions(-) diff --git a/test-case/multiple-pipeline-capture.sh b/test-case/multiple-pipeline-capture.sh index f99fdeb6..d9350d4b 100755 --- a/test-case/multiple-pipeline-capture.sh +++ b/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 $? From 174ca35300aba0718df1f1d7b2bac920a0c72483 Mon Sep 17 00:00:00 2001 From: Pan Xiuli Date: Wed, 28 Oct 2020 05:47:36 +0000 Subject: [PATCH 10/16] test-case: simultaneous-playback-capture: check kernel log in each iteration remove the redundant kernel log check for all case. enable kernel log check for each iteration. Signed-off-by: Pan Xiuli --- test-case/simultaneous-playback-capture.sh | 11 ++++------- 1 file changed, 4 insertions(+), 7 deletions(-) diff --git a/test-case/simultaneous-playback-capture.sh b/test-case/simultaneous-playback-capture.sh index 927b31b5..6bd64ef5 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_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 $? From 677a62e7fad47626b238451d4c2798594af8c62c Mon Sep 17 00:00:00 2001 From: Pan Xiuli Date: Wed, 18 Nov 2020 04:02:53 +0000 Subject: [PATCH 11/16] lib: add journalctl_cmd warpper for journalctl add some style options for the journalctl to unify all journalctl output format Signed-off-by: Pan Xiuli --- case-lib/lib.sh | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/case-lib/lib.sh b/case-lib/lib.sh index 8eac28ec..50606d35 100644 --- a/case-lib/lib.sh +++ b/case-lib/lib.sh @@ -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 "$@" +} From e534c234682f7a1f44f3307aaf61be816c567b00 Mon Sep 17 00:00:00 2001 From: Pan Xiuli Date: Fri, 23 Oct 2020 11:09:40 +0000 Subject: [PATCH 12/16] test: verify-sof-firmware-load: use journalctl to get kernel logs Directly use journalctl in the testcase to avoid kernel log missing issues. Signed-off-by: Pan Xiuli --- test-case/verify-sof-firmware-load.sh | 22 ++++++++-------------- 1 file changed, 8 insertions(+), 14 deletions(-) diff --git a/test-case/verify-sof-firmware-load.sh b/test-case/verify-sof-firmware-load.sh index 428159c1..63dc6aa4 100755 --- a/test-case/verify-sof-firmware-load.sh +++ b/test-case/verify-sof-firmware-load.sh @@ -20,13 +20,11 @@ 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;}' ) + +cmd="journalctl_cmd" dlogi "Checking SOF Firmware load info in kernel log" if $cmd | grep -q " sof-audio.*Firmware.*version"; then @@ -36,12 +34,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_cmd --lines 50 || true + printf ' ------\n debugging with systemd journalctl \n ---- \n' + systemctl status systemd-journald* || true die "Cannot find the sof audio version" fi From 7a23ad681f0eecc9eb720bcadadfe8d2f22d14cb Mon Sep 17 00:00:00 2001 From: Pan Xiuli Date: Thu, 22 Oct 2020 09:50:31 +0000 Subject: [PATCH 13/16] tools: sof-get-default-tplg: use journalctl as default kernel log reader use journalctl by default for any kernel log reader usage. Also add headter for the file. Signed-off-by: Pierre-Louis Bossart Signed-off-by: Pan Xiuli --- tools/sof-get-default-tplg.sh | 20 +++++++++----------- 1 file changed, 9 insertions(+), 11 deletions(-) diff --git a/tools/sof-get-default-tplg.sh b/tools/sof-get-default-tplg.sh index 4e0d4217..c6948c23 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 "" From fe193359623c60c7d33503dbe35eead67bb682b4 Mon Sep 17 00:00:00 2001 From: Pan Xiuli Date: Fri, 23 Oct 2020 09:14:20 +0000 Subject: [PATCH 14/16] tools: sof-kernel-log-check: fix script direct run Add path for the sof-dump-status.py to avoid error: sof-dump-status.py: command not found Signed-off-by: Pan Xiuli --- tools/sof-kernel-log-check.sh | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tools/sof-kernel-log-check.sh b/tools/sof-kernel-log-check.sh index 3ff5afb6..657ccd64 100755 --- a/tools/sof-kernel-log-check.sh +++ b/tools/sof-kernel-log-check.sh @@ -130,7 +130,7 @@ begin_line=${1:-1} declare err_str ignore_str -platform=$(sof-dump-status.py -p) +platform=$($(dirname "$0")/sof-dump-status.py -p) err_str="error|failed|timed out|panic|oops" From f2f39ec1d3a8a7174d480e590acc7ffb07b9aa2e Mon Sep 17 00:00:00 2001 From: Pan Xiuli Date: Wed, 11 Nov 2020 06:41:00 +0000 Subject: [PATCH 15/16] tools: sof-kernel-log-check: use journalctl to get kernel logs use journalctl to get kernl logs. use timestamp as checkpoint to split logs for each test case. Signed-off-by: Pierre-Louis Bossart Signed-off-by: Pan Xiuli --- case-lib/lib.sh | 2 +- tools/sof-kernel-log-check.sh | 43 ++++++++++++----------------------- 2 files changed, 15 insertions(+), 30 deletions(-) diff --git a/case-lib/lib.sh b/case-lib/lib.sh index 50606d35..07504204 100644 --- a/case-lib/lib.sh +++ b/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 diff --git a/tools/sof-kernel-log-check.sh b/tools/sof-kernel-log-check.sh index 657ccd64..4cdb8209 100755 --- a/tools/sof-kernel-log-check.sh +++ b/tools/sof-kernel-log-check.sh @@ -126,13 +126,12 @@ # 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=$($(dirname "$0")/sof-dump-status.py -p) - -err_str="error|failed|timed out|panic|oops" +# pwd resolves relative paths +my_dir=$(cd "$(dirname "${BASH_SOURCE[0]}")" && pwd) +platform=$("$my_dir"/sof-dump-status.py -p) # TODO explain # The first string cannot start by | @@ -250,32 +249,18 @@ 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" +# 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 -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 +declare -p cmd +# check priority err for error message +[[ "$ignore_str" ]] && err=$($cmd --priority=err | grep -vE "$ignore_str") || $($cmd --priority=err) -if [ "$err" ]; then - echo "$(date -u '+%Y-%m-%d %T %Z')" "[ERROR]" "Caught dmesg error" +[[ -z "$err" ]] || { + echo "$(date -u '+%Y-%m-%d %T %Z')" "[ERROR]" "Caught kernel log error" echo "===========================>>" echo "$err" echo "<<===========================" builtin exit 1 -fi +} From 9f78af566798845c383ca88bba6edd0bd92e2415 Mon Sep 17 00:00:00 2001 From: Pan Xiuli Date: Wed, 28 Oct 2020 04:06:24 +0000 Subject: [PATCH 16/16] tools: sof-kernel-log-check: add some common error logs can be ignored Add common error logs from systemd, initramfs, atkbd, i801_smbus, ata3, genirq, DMAR, dw_dmac, proc_thermal, SDWm, touch pad Those error level logs did not break functionality of the DUTs. Signed-off-by: Pan Xiuli --- tools/sof-kernel-log-check.sh | 60 +++++++++++++++++++++++++++++++++++ 1 file changed, 60 insertions(+) diff --git a/tools/sof-kernel-log-check.sh b/tools/sof-kernel-log-check.sh index 4cdb8209..7e255f06 100755 --- a/tools/sof-kernel-log-check.sh +++ b/tools/sof-kernel-log-check.sh @@ -249,6 +249,66 @@ case "$platform" in ;; esac +# below are new error level kernel logs from journalctl --priority=err +# that did not influence 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"