From 20aae78461a028044a6cdd7df34416900f4baffa Mon Sep 17 00:00:00 2001 From: Pan Xiuli Date: Fri, 23 Oct 2020 11:09:40 +0000 Subject: [PATCH 1/4] 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..f6a601de 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 -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 +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 -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 From 20fc97af5d23139d3a09cb7f99d45e99fe24d58d Mon Sep 17 00:00:00 2001 From: Pan Xiuli Date: Thu, 22 Oct 2020 09:50:31 +0000 Subject: [PATCH 2/4] tools: sof-get-default-tplg: use journalctl as default kernel log reader use journalctl by default for any kernel log reader usage. Also add header 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 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 "" From df180205c6a4f8616a7dfa11fffbe5caf76bd24e Mon Sep 17 00:00:00 2001 From: Pan Xiuli Date: Fri, 23 Oct 2020 09:14:20 +0000 Subject: [PATCH 3/4] 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 2fe11ae8..c734648c 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 8bfe0bdfea4da042c34a50b09652af2a5c3d7c73 Mon Sep 17 00:00:00 2001 From: Pan Xiuli Date: Mon, 2 Nov 2020 07:32:28 +0000 Subject: [PATCH 4/4] tools: sof-kernel-log-check: use journalctl to get kernel logs use journalctl to get kernl logs. use timestamp to split logs for each test case. replace all test case to use the timestamp Signed-off-by: Pierre-Louis Bossart Signed-off-by: Pan Xiuli --- case-lib/config.sh | 6 ++-- case-lib/lib.sh | 4 +-- test-case/check-capture.sh | 4 +-- test-case/check-fw-echo-reference.sh | 4 +-- test-case/check-ipc-flood.sh | 4 +-- test-case/check-keyword-detection.sh | 4 +-- test-case/check-kmod-load-unload.sh | 10 +++--- .../check-pause-release-suspend-resume.sh | 4 +-- test-case/check-pause-resume.sh | 4 +-- test-case/check-playback.sh | 4 +-- test-case/check-runtime-pm-double-active.sh | 4 +-- test-case/check-runtime-pm-status.sh | 4 +-- test-case/check-signal-stop-start.sh | 4 +-- test-case/check-smart-amplifier.sh | 4 +-- test-case/check-suspend-resume-with-audio.sh | 4 +-- test-case/check-suspend-resume.sh | 4 +-- test-case/check-xrun-injection.sh | 4 +-- test-case/multiple-pause-resume.sh | 4 +-- test-case/multiple-pipeline-capture.sh | 4 +-- test-case/multiple-pipeline-playback.sh | 4 +-- test-case/simultaneous-playback-capture.sh | 4 +-- test-case/test-speaker.sh | 4 +-- test-case/volume-basic-test.sh | 4 +-- tools/sof-kernel-log-check.sh | 31 ++++++------------- 24 files changed, 60 insertions(+), 71 deletions(-) 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 e3580a22..88249eb6 100644 --- a/case-lib/lib.sh +++ b/case-lib/lib.sh @@ -38,10 +38,10 @@ if [ ! "$SOFCARD" ]; then SOFCARD=$(grep -v 'sof-probes' /proc/asound/cards | grep 'sof-[a-z]' | 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 c09992f2..809cf355 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 87d19144..3ef46e51 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..a34f808f 100755 --- a/test-case/check-ipc-flood.sh +++ b/test-case/check-ipc-flood.sh @@ -32,7 +32,7 @@ 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" @@ -54,5 +54,5 @@ do dmesg | grep "IPC Flood count" -A 2 done -sof-kernel-log-check.sh $KERNEL_LAST_LINE +sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP exit 0 diff --git a/test-case/check-keyword-detection.sh b/test-case/check-keyword-detection.sh index ca4e61f6..fb64aa56 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 39aa5a43..85db4774 100755 --- a/test-case/check-pause-resume.sh +++ b/test-case/check-pause-resume.sh @@ -75,7 +75,7 @@ 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 +func_lib_setup_kernel_last_timestamp for idx in $(seq 0 $(expr $PIPELINE_COUNT - 1)) do channel=$(func_pipeline_parse_value $idx channel) @@ -126,5 +126,5 @@ END sof-kernel-log-check.sh 0 || die "Catch error in dmesg" done -sof-kernel-log-check.sh $KERNEL_LAST_LINE +sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP exit $? diff --git a/test-case/check-playback.sh b/test-case/check-playback.sh index 6a59e4ee..f37d1c93 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 120e6617..c5d65ed0 100755 --- a/test-case/check-runtime-pm-double-active.sh +++ b/test-case/check-runtime-pm-double-active.sh @@ -71,7 +71,7 @@ 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 +func_lib_setup_kernel_last_timestamp for idx in $(seq 0 $(expr $PIPELINE_COUNT - 1)) do @@ -141,5 +141,5 @@ do sof-kernel-log-check.sh 0 || die "Catch error in dmesg" done -sof-kernel-log-check.sh $KERNEL_LAST_LINE +sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP exit $? diff --git a/test-case/check-runtime-pm-status.sh b/test-case/check-runtime-pm-status.sh index 3b47da01..66700b9a 100755 --- a/test-case/check-runtime-pm-status.sh +++ b/test-case/check-runtime-pm-status.sh @@ -65,7 +65,7 @@ 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 +func_lib_setup_kernel_last_timestamp for idx in $(seq 0 $(expr $PIPELINE_COUNT - 1)) do @@ -127,5 +127,5 @@ do sof-kernel-log-check.sh 0 || die "Catch error in dmesg" done -sof-kernel-log-check.sh $KERNEL_LAST_LINE +sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP exit $? diff --git a/test-case/check-signal-stop-start.sh b/test-case/check-signal-stop-start.sh index 7ce79052..498f48ad 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 db5a4363..7796844a 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 4585675d..4278feea 100755 --- a/test-case/check-suspend-resume-with-audio.sh +++ b/test-case/check-suspend-resume-with-audio.sh @@ -53,7 +53,7 @@ OPT_PARM_lst['f']=1 OPT_VALUE_lst['f']='' func_opt_parse_option "$@" func_lib_check_sudo -func_lib_setup_kernel_last_line +func_lib_setup_kernel_last_timestamp tplg=${OPT_VALUE_lst['t']} [[ ${OPT_VALUE_lst['s']} -eq 1 ]] && func_lib_start_log_collect @@ -131,4 +131,4 @@ do done # check full log -sof-kernel-log-check.sh $KERNEL_LAST_LINE +sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP diff --git a/test-case/check-suspend-resume.sh b/test-case/check-suspend-resume.sh index d62f6a93..43159028 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 @@ -91,5 +91,5 @@ do done # check full log -sof-kernel-log-check.sh $KERNEL_LAST_LINE +sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP exit $? diff --git a/test-case/check-xrun-injection.sh b/test-case/check-xrun-injection.sh index 55f5cbf5..f0c81a2e 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 bee7d074..2fe0da12 100755 --- a/test-case/multiple-pause-resume.sh +++ b/test-case/multiple-pause-resume.sh @@ -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 @@ -190,5 +190,5 @@ do sof-kernel-log-check.sh 0 || die "Catch error in dmesg" done -sof-kernel-log-check.sh $KERNEL_LAST_LINE +sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP exit $? diff --git a/test-case/multiple-pipeline-capture.sh b/test-case/multiple-pipeline-capture.sh index 084760ae..57ff22d9 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 @@ -154,5 +154,5 @@ do sof-kernel-log-check.sh 0 || die "Catch error in dmesg" done -sof-kernel-log-check.sh $KERNEL_LAST_LINE >/dev/null +sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP >/dev/null exit $? diff --git a/test-case/multiple-pipeline-playback.sh b/test-case/multiple-pipeline-playback.sh index 88b3e294..a7d7a19f 100755 --- a/test-case/multiple-pipeline-playback.sh +++ b/test-case/multiple-pipeline-playback.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 @@ -154,5 +154,5 @@ do sof-kernel-log-check.sh 0 || die "Catch error in dmesg" done -sof-kernel-log-check.sh $KERNEL_LAST_LINE >/dev/null +sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP >/dev/null exit $? diff --git a/test-case/simultaneous-playback-capture.sh b/test-case/simultaneous-playback-capture.sh index fbb0c0ca..c567c9ef 100755 --- a/test-case/simultaneous-playback-capture.sh +++ b/test-case/simultaneous-playback-capture.sh @@ -57,7 +57,7 @@ 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_lib_setup_kernel_last_timestamp func_error_exit() { @@ -115,5 +115,5 @@ do sof-kernel-log-check.sh 0 || die "Catch error in dmesg" done -sof-kernel-log-check.sh $KERNEL_LAST_LINE > /dev/null +sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP > /dev/null exit $? diff --git a/test-case/test-speaker.sh b/test-case/test-speaker.sh index 3c4f81e6..20d88d66 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/volume-basic-test.sh b/test-case/volume-basic-test.sh index ff374711..7d3df61c 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-kernel-log-check.sh b/tools/sof-kernel-log-check.sh index c734648c..20efdf5f 100755 --- a/tools/sof-kernel-log-check.sh +++ b/tools/sof-kernel-log-check.sh @@ -127,7 +127,7 @@ # than deleting it. -begin_line=${1:-1} +begin_timestamp=${1:-0} declare err_str ignore_str platform=$($(dirname "$0")/sof-dump-status.py -p) @@ -241,32 +241,21 @@ 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_timestamp is in UNIX timestamp format, otherwise use dmesg +journalctlflag="-k -q --no-pager --utc --output=short-iso --no-hostname" +[[ $begin_timestamp =~ ^[0-9]{10} ]] && cmd="journalctl $journalctlflag --since=@$begin_timestamp" || cmd="dmesg" -# 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 +declare -p cmd if [ "$ignore_str" ]; then - err=$( $cmd | grep 'Call Trace' -A5 -B3)$( $cmd | grep -E "$err_str"|grep -vE "$ignore_str") + 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") + 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" +[[ -z "$err" ]] || { + echo "$(date -u '+%Y-%m-%d %T %Z')" "[ERROR]" "Caught kernel log error" echo "===========================>>" echo "$err" echo "<<===========================" builtin exit 1 -fi +}