diff --git a/case-lib/hijack.sh b/case-lib/hijack.sh index 25b3690a..8ebfcf54 100644 --- a/case-lib/hijack.sh +++ b/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 is not properly setup" 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 diff --git a/case-lib/lib.sh b/case-lib/lib.sh index 5a287fd5..2b86f2aa 100644 --- a/case-lib/lib.sh +++ b/case-lib/lib.sh @@ -40,10 +40,11 @@ if [ ! "$SOFCARD" ]; then awk '/sof-[a-z]/ && $1 ~ /^[0-9]+$/ { $1=$1; print $1; exit 0;}') fi -func_lib_setup_kernel_checkpoint() +setup_kernel_check_point() { - # shellcheck disable=SC2034 # external script will use it - KERNEL_CHECKPOINT=$(date +%s) + # There is a 5s delay between two cases by sof-framework, + # make the check point 5s earlier to avoid log loss. + export KERNEL_CHECKPOINT=$(($(date +%s) - 5)) } # This function adds a fake error to dmesg (which is always saved by @@ -326,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; @@ -342,5 +336,5 @@ is_sof_used() journalctl_cmd() { journalctl -k -q --no-pager --utc --output=short-monotonic \ - --no-hostname "$@" + --no-hostname --boot "$@" } diff --git a/test-case/check-alsabat.sh b/test-case/check-alsabat.sh index f4110ce5..5119aeda 100755 --- a/test-case/check-alsabat.sh +++ b/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']} diff --git a/test-case/check-capture.sh b/test-case/check-capture.sh index 093a2937..a448948f 100755 --- a/test-case/check-capture.sh +++ b/test-case/check-capture.sh @@ -59,7 +59,7 @@ file_prefix=${OPT_VAL['f']} [[ ${OPT_VAL['s']} -eq 1 ]] && func_lib_start_log_collect -func_lib_setup_kernel_checkpoint +setup_kernel_check_point func_lib_check_sudo func_pipeline_export "$tplg" "type:capture & ${OPT_VAL['S']}" diff --git a/test-case/check-fw-echo-reference.sh b/test-case/check-fw-echo-reference.sh index c7801bb4..4a66748b 100755 --- a/test-case/check-fw-echo-reference.sh +++ b/test-case/check-fw-echo-reference.sh @@ -44,7 +44,7 @@ frequency=${OPT_VAL['f']} [[ ${OPT_VAL['s']} -eq 1 ]] && func_lib_start_log_collect func_pipeline_export "$tplg" "echo:any" -func_lib_setup_kernel_checkpoint +setup_kernel_check_point if [ "$PIPELINE_COUNT" != "2" ]; then die "Only detect $PIPELINE_COUNT pipeline(s) from topology, but two are needed" diff --git a/test-case/check-ipc-flood.sh b/test-case/check-ipc-flood.sh index e3993a9c..f6f7a70f 100755 --- a/test-case/check-ipc-flood.sh +++ b/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']} @@ -44,7 +45,7 @@ do # cleanup dmesg buffer for each iteration sudo dmesg -c > /dev/null # set up timestamp for each iteration - func_lib_setup_kernel_checkpoint + setup_kernel_check_point 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'" diff --git a/test-case/check-keyword-detection.sh b/test-case/check-keyword-detection.sh index 9e4d85da..bec4c1da 100755 --- a/test-case/check-keyword-detection.sh +++ b/test-case/check-keyword-detection.sh @@ -55,7 +55,7 @@ duration=${OPT_VAL['d']} [[ ${OPT_VAL['s']} -eq 1 ]] && func_lib_start_log_collect func_pipeline_export "$tplg" "kpbm:any" -func_lib_setup_kernel_checkpoint +setup_kernel_check_point if test "$PIPELINE_COUNT" != "1"; then die "detected $PIPELINE_COUNT wov pipeline(s) from topology, but 1 is needed" diff --git a/test-case/check-kmod-load-unload-after-playback.sh b/test-case/check-kmod-load-unload-after-playback.sh index 30ccd58e..5b2a8528 100755 --- a/test-case/check-kmod-load-unload-after-playback.sh +++ b/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 diff --git a/test-case/check-kmod-load-unload.sh b/test-case/check-kmod-load-unload.sh index bea03401..aedaf317 100755 --- a/test-case/check-kmod-load-unload.sh +++ b/test-case/check-kmod-load-unload.sh @@ -33,7 +33,7 @@ OPT_NAME['p']='pulseaudio' OPT_DESC['p']='disable pulseaudio on the test proce OPT_HAS_ARG['p']=0 OPT_VAL['p']=1 func_opt_parse_option "$@" -func_lib_setup_kernel_checkpoint +setup_kernel_check_point loop_cnt=${OPT_VAL['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_checkpoint + setup_kernel_check_point # After module removal, it takes about 10s for "aplay -l" to show # device list, within this 10s, it shows "no soundcard found". Here @@ -78,7 +78,7 @@ do sof-kernel-log-check.sh "$KERNEL_CHECKPOINT" || die "error found after kmod unload is real error, failing" - func_lib_setup_kernel_checkpoint + setup_kernel_check_point dlogi "run kmod/sof_insert.sh" sudo sof_insert.sh || { # FIXME: don't exit the status of dloge(). Use die() diff --git a/test-case/check-pause-release-suspend-resume.sh b/test-case/check-pause-release-suspend-resume.sh index 40135285..ab389f0d 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_VAL['s']} -eq 1 ]] && func_lib_start_log_collect -func_lib_setup_kernel_checkpoint +setup_kernel_check_point 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" diff --git a/test-case/check-pause-resume.sh b/test-case/check-pause-resume.sh index da1265d7..788718e7 100755 --- a/test-case/check-pause-resume.sh +++ b/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']} @@ -81,7 +82,7 @@ func_pipeline_export "$tplg" "type:$test_mode & ${OPT_VAL['S']}" for idx in $(seq 0 $((PIPELINE_COUNT - 1))) do # set up checkpoint for each iteration - func_lib_setup_kernel_checkpoint + setup_kernel_check_point channel=$(func_pipeline_parse_value "$idx" channel) rate=$(func_pipeline_parse_value "$idx" rate) fmt=$(func_pipeline_parse_value "$idx" fmt) diff --git a/test-case/check-playback.sh b/test-case/check-playback.sh index abf3c133..d29621ae 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_checkpoint +setup_kernel_check_point func_lib_check_sudo func_pipeline_export "$tplg" "type:playback & ${OPT_VAL['S']}" diff --git a/test-case/check-reboot.sh b/test-case/check-reboot.sh index 7abaebc0..d6bd8b15 100755 --- a/test-case/check-reboot.sh +++ b/test-case/check-reboot.sh @@ -150,7 +150,8 @@ $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 +export KERNEL_CHECKPOINT bash -c '$full_cmd' exit 0 diff --git a/test-case/check-runtime-pm-double-active.sh b/test-case/check-runtime-pm-double-active.sh index e21e0ab3..8dd79a7d 100755 --- a/test-case/check-runtime-pm-double-active.sh +++ b/test-case/check-runtime-pm-double-active.sh @@ -89,7 +89,7 @@ do for i in $(seq 1 $loop_count) do # set up checkpoint for each iteration - func_lib_setup_kernel_checkpoint + setup_kernel_check_point 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" diff --git a/test-case/check-runtime-pm-status.sh b/test-case/check-runtime-pm-status.sh index 8d4a7697..6bfad273 100755 --- a/test-case/check-runtime-pm-status.sh +++ b/test-case/check-runtime-pm-status.sh @@ -83,7 +83,7 @@ do for i in $(seq 1 $loop_count) do # set up checkpoint for each iteration - func_lib_setup_kernel_checkpoint + setup_kernel_check_point 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" diff --git a/test-case/check-signal-stop-start.sh b/test-case/check-signal-stop-start.sh index ec734505..bcfdcd53 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_checkpoint +setup_kernel_check_point func_stop_start_pipeline() { diff --git a/test-case/check-smart-amplifier.sh b/test-case/check-smart-amplifier.sh index a3702a69..633b0306 100755 --- a/test-case/check-smart-amplifier.sh +++ b/test-case/check-smart-amplifier.sh @@ -59,7 +59,7 @@ tplg=${OPT_VAL['t']} [[ ${OPT_VAL['s']} -eq 1 ]] && func_lib_start_log_collect func_pipeline_export "$tplg" "smart_amp:any" -func_lib_setup_kernel_checkpoint +setup_kernel_check_point [ "$PIPELINE_COUNT" == "2" ] || die "Only detect $PIPELINE_COUNT pipeline(s) from topology, but two are needed" diff --git a/test-case/check-sof-logger.sh b/test-case/check-sof-logger.sh index 5a9addfe..037e0bbd 100755 --- a/test-case/check-sof-logger.sh +++ b/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 diff --git a/test-case/check-suspend-resume-with-audio.sh b/test-case/check-suspend-resume-with-audio.sh index 8228f844..4d3cdad7 100755 --- a/test-case/check-suspend-resume-with-audio.sh +++ b/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']} @@ -91,7 +92,7 @@ fi for idx in $(seq 0 $(expr $PIPELINE_COUNT - 1)) do # set up checkpoint for each iteration - func_lib_setup_kernel_checkpoint + setup_kernel_check_point # store local checkpoint as we have sub-test LOCAL_CHECK_POINT="$KERNEL_CHECKPOINT" channel=$(func_pipeline_parse_value $idx channel) diff --git a/test-case/check-suspend-resume.sh b/test-case/check-suspend-resume.sh index 1af2a73a..6718a4e6 100755 --- a/test-case/check-suspend-resume.sh +++ b/test-case/check-suspend-resume.sh @@ -74,7 +74,7 @@ for i in $(seq 1 $loop_count) do dlogi "===== Round($i/$loop_count) =====" # set up checkpoint for each iteration - func_lib_setup_kernel_checkpoint + setup_kernel_check_point 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]} diff --git a/test-case/check-xrun-injection.sh b/test-case/check-xrun-injection.sh index 1a641f17..57b066cf 100755 --- a/test-case/check-xrun-injection.sh +++ b/test-case/check-xrun-injection.sh @@ -43,7 +43,7 @@ interval=${OPT_VAL['i']} [[ ${OPT_VAL['s']} -eq 1 ]] && func_lib_start_log_collect -func_lib_setup_kernel_checkpoint +setup_kernel_check_point func_lib_check_sudo case $test_mode in diff --git a/test-case/multiple-pause-resume.sh b/test-case/multiple-pause-resume.sh index 809cad3d..58e85795 100755 --- a/test-case/multiple-pause-resume.sh +++ b/test-case/multiple-pause-resume.sh @@ -145,7 +145,7 @@ for i in $(seq 1 $loop_count) do dlogi "===== Loop count( $i / $loop_count ) =====" # set up checkpoint for each iteration - func_lib_setup_kernel_checkpoint + setup_kernel_check_point for pipeline_combine_str in "${pipeline_combine_lst[@]}" do unset pid_lst diff --git a/test-case/multiple-pipeline.sh b/test-case/multiple-pipeline.sh index 445264eb..5721f30b 100755 --- a/test-case/multiple-pipeline.sh +++ b/test-case/multiple-pipeline.sh @@ -144,7 +144,7 @@ ps_checks() for i in $(seq 1 $loop_cnt) do # set up checkpoint for each iteration - func_lib_setup_kernel_checkpoint + setup_kernel_check_point dlogi "===== Testing: (Loop: $i/$loop_cnt) =====" # start playback or capture: diff --git a/test-case/simultaneous-playback-capture.sh b/test-case/simultaneous-playback-capture.sh index 65801ba2..e2c242a4 100755 --- a/test-case/simultaneous-playback-capture.sh +++ b/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']} @@ -69,7 +71,7 @@ func_error_exit() for i in $(seq 1 $loop_cnt) do # set up checkpoint for each iteration - func_lib_setup_kernel_checkpoint + setup_kernel_check_point dlogi "===== Testing: (Loop: $i/$loop_cnt) =====" # 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)) diff --git a/test-case/test-speaker.sh b/test-case/test-speaker.sh index 29ca21b9..19e52417 100755 --- a/test-case/test-speaker.sh +++ b/test-case/test-speaker.sh @@ -32,7 +32,7 @@ tplg=${OPT_VAL['t']} func_pipeline_export "$tplg" "type:playback" tcnt=${OPT_VAL['l']} -func_lib_setup_kernel_checkpoint +setup_kernel_check_point for idx in $(seq 0 $(expr $PIPELINE_COUNT - 1)) do channel=$(func_pipeline_parse_value $idx channel) diff --git a/test-case/verify-firmware-presence.sh b/test-case/verify-firmware-presence.sh index 1af11ecf..efae6288 100755 --- a/test-case/verify-firmware-presence.sh +++ b/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) diff --git a/test-case/verify-kernel-module-load-probe.sh b/test-case/verify-kernel-module-load-probe.sh index 962cb684..b836bf60 100755 --- a/test-case/verify-kernel-module-load-probe.sh +++ b/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\"" diff --git a/test-case/verify-pcm-list.sh b/test-case/verify-pcm-list.sh index 2aca63cf..739ba03d 100755 --- a/test-case/verify-pcm-list.sh +++ b/test-case/verify-pcm-list.sh @@ -29,8 +29,7 @@ tplg=${OPT_VAL['t']} tplg_path=`func_lib_get_tplg_path "$tplg"` [[ "$?" != "0" ]] && 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})" diff --git a/test-case/verify-sof-firmware-load.sh b/test-case/verify-sof-firmware-load.sh index 63dc6aa4..6a509c91 100755 --- a/test-case/verify-sof-firmware-load.sh +++ b/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;}' ) +alias | grep -q 'Sub-Test' || setup_kernel_check_point cmd="journalctl_cmd" diff --git a/test-case/verify-tplg-binary.sh b/test-case/verify-tplg-binary.sh index 0f7905ea..1ed4c2cf 100755 --- a/test-case/verify-tplg-binary.sh +++ b/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"` diff --git a/test-case/volume-basic-test.sh b/test-case/volume-basic-test.sh index 166695b0..dd2bce3b 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_checkpoint + setup_kernel_check_point dlogi "===== Round($i/$maxloop) =====" # TODO: need to check command effect for i in "${pgalist[@]}"