From a0e3463804ecc06c60c05c192c7c1771cee3f8e0 Mon Sep 17 00:00:00 2001 From: "Wu, BinX" Date: Wed, 6 May 2020 21:59:41 +0800 Subject: [PATCH 1/4] tools: sof-kernel-dump: use journalctl command to query kernel log use journalctl command instead of this step: 1. get kernel bootup line number by sof-get-kernel-line.sh 2. user step 1 information to dump the kernel log from /var/log/kern.log file now direct use journalctl to dump the kernel log after system bootup Signed-off-by: Wu, BinX --- README.md | 2 +- tools/sof-kernel-dump.sh | 37 ++++++------------------------------- 2 files changed, 7 insertions(+), 32 deletions(-) diff --git a/README.md b/README.md index 4ed73f39..d859e0fa 100644 --- a/README.md +++ b/README.md @@ -113,7 +113,7 @@ apl with the most recent * sof-kernel-dump.sh -
Catch all kernel information after system boot up from /var/log/kern.log file +
Catch all kernel information after system boot up by `journalctl` command * sof-kernel-log-check.sh
Check dmesg for errors and ensure that any found are real errors diff --git a/tools/sof-kernel-dump.sh b/tools/sof-kernel-dump.sh index e2f0458c..09909154 100755 --- a/tools/sof-kernel-dump.sh +++ b/tools/sof-kernel-dump.sh @@ -1,35 +1,10 @@ #!/bin/bash # dump the kernel information from target -last_order=${1:-0} +reverse_order=${1:-0} # check whether parameter 1 has the Non-Number -[[ "${last_order//[0-9]/}" ]] && echo "$0 parameter 1 just support +N number, N start from 0" && builtin exit 1 -last_order=$[ $last_order + 1 ] -log_file=${2:-"/var/log/kern.log"} -# check whether target file exists -[[ ! -f "$log_file" ]] && echo "$0 parameter 2 $log_file does not exist" && builtin exit 1 -# load helper script -which sof-get-kernel-line.sh 2>&1 1>/dev/null -if [ $? -eq 0 ]; then - kernel_line_script="sof-get-kernel-line.sh" -else - cd $(dirname $0) - kernel_line_script=$PWD/sof-get-kernel-line.sh - cd $OLDPWD -fi -declare -a line_lst -# here line lst to keep 2 value, [0] is target line, [1] is end line -# if target is last one, so will cut content form [0] -> file end -# if target is second last, so will cut content from [0] -> [1] -line_lst=($($kernel_line_script $log_file|tail -n $last_order|awk '{print $1;}')) -# sof-get-kernel-line.sh dump nothing -[[ ! "${line_lst[0]}" ]] && echo "$0 without catch system boot keyword" && builtin exit 1 -# check target is last one -if [ ! "${line_lst[1]}" ];then - # tr '\0' ' ' to fix warning message: "command substitution: ignored null byte in input" - tail -n +${line_lst[0]} $log_file|tr '\0' ' '|cut -f5- -d ' ' -else - line_count=$[ ${line_lst[1]} - ${line_lst[0]} ] - # tr '\0' ' ' to fix warning message: "command substitution: ignored null byte in input" - tail -n +${line_lst[0]} $log_file|tr '\0' ' '|head -n $line_count|cut -f5- -d ' ' -fi +[[ "${reverse_order//[0-9]/}" ]] && echo "$0 parameter 1 just support +N number, N start from 0" && builtin exit 1 +# format time stamp output for journalctl command +LC_TIME='en_US.UTF-8' +journalctl --flush +journalctl --boot="$reverse_order" --dmesg --no-pager --no-hostname -o short-precise From 5d95b801e8118fa9236845d8607aebb89c37c58f Mon Sep 17 00:00:00 2001 From: "Wu, BinX" Date: Wed, 10 Jun 2020 13:58:36 +0800 Subject: [PATCH 2/4] test-case: verify-sof-firware-load: update filter of fireware keyword with replace kern.log file the keyword filter already changed from '] sof-audio' to 'sof-audio' so need refine the case filter Signed-off-by: Wu, BinX --- test-case/verify-sof-firmware-load.sh | 21 ++++++++++++--------- 1 file changed, 12 insertions(+), 9 deletions(-) diff --git a/test-case/verify-sof-firmware-load.sh b/test-case/verify-sof-firmware-load.sh index 8d6763b2..6af6009d 100755 --- a/test-case/verify-sof-firmware-load.sh +++ b/test-case/verify-sof-firmware-load.sh @@ -13,25 +13,28 @@ ## # source from the relative path of current folder -source $(dirname ${BASH_SOURCE[0]})/../case-lib/lib.sh +# shellcheck disable=SC1090 +source "$(dirname "${BASH_SOURCE[0]}")/../case-lib/lib.sh" func_opt_parse_option "$@" -if [ ! "$(alias |grep 'Sub-Test')" ];then - # hijack DMESG_LOG_START_LINE which refer dump kernel log in exit function +if alias |grep -q 'Sub-Test' ;then + cmd="dmesg" +else + # hijack CASE_KERNEL_START_TIME which refer dump kernel log in exit function + # shellcheck disable=SC2034 DMESG_LOG_START_LINE=$(sof-get-kernel-line.sh|tail -n 1 |awk '{print $1;}') cmd="sof-kernel-dump.sh" -else - cmd="dmesg" fi dlogi "Checking SOF Firmware load info in kernel log" -if [[ $(eval $cmd | grep "] sof-audio.*version") ]]; then +eval $cmd | grep -q "sof-audio.*Firmware.*version" && { # dump the version info and ABI info eval $cmd | grep "Firmware info" -A1 # dump the debug info eval $cmd | grep "Firmware debug build" -A3 exit 0 -else - dloge "Cannot find the sof audio version" && exit 1 -fi +} + +dloge "Cannot find the sof audio version" +exit 1 From 419ee3e0fc19468fca62ac9905baf6f647c084e2 Mon Sep 17 00:00:00 2001 From: "Wu, BinX" Date: Thu, 7 May 2020 10:08:08 +0800 Subject: [PATCH 3/4] tools: sof-kernel-log-check: use journalctl command to query kernel log use journalctl command instead of query the begin line from /var/log/kern.log file This change also modify all script which refer load sof-kernel-log-check file Signed-off-by: Wu, BinX --- case-lib/config.sh | 5 --- case-lib/lib.sh | 6 ++-- test-case/check-capture.sh | 4 +-- test-case/check-ipc-flood.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-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 | 2 +- tools/sof-kernel-log-check.sh | 36 ++++++++++--------- 21 files changed, 61 insertions(+), 62 deletions(-) diff --git a/case-lib/config.sh b/case-lib/config.sh index 96b6c9d4..a53136e7 100644 --- a/case-lib/config.sh +++ b/case-lib/config.sh @@ -17,11 +17,6 @@ TPLG_ROOT=${TPLG_ROOT:-/lib/firmware/intel/sof-tplg} declare -A TPLG_IGNORE_LST TPLG_IGNORE_LST['pcm']='HDA Digital,Media Playback,DMIC16k' -# 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 - # If not set will be automatically set by logging_ctl function # Test case log root # EXAMPLE: the log for test-case/check-ipc-flood.sh will be stored at diff --git a/case-lib/lib.sh b/case-lib/lib.sh index 9803544b..3942fe60 100644 --- a/case-lib/lib.sh +++ b/case-lib/lib.sh @@ -38,10 +38,12 @@ 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_time() { # shellcheck disable=SC2034 # external script will use it - KERNEL_LAST_LINE=$(wc -l /var/log/kern.log|awk '{print $1;}') + KERNEL_LAST_TIME=$(journalctl --dmesg --no-pager -n 1 -o short-iso-precise|awk '/kernel/ {print $1;}') + KERNEL_LAST_TIME=${KERNEL_LAST_TIME:0:-5} + KERNEL_LAST_TIME=${KERNEL_LAST_TIME/T/ } } SOF_LOG_COLLECT=0 diff --git a/test-case/check-capture.sh b/test-case/check-capture.sh index 99d7ad72..dd281052 100755 --- a/test-case/check-capture.sh +++ b/test-case/check-capture.sh @@ -56,7 +56,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_time func_lib_check_sudo func_pipeline_export $tplg "type:capture & ${OPT_VALUE_lst['S']}" @@ -104,5 +104,5 @@ do done done -sof-kernel-log-check.sh $KERNEL_LAST_LINE +sof-kernel-log-check.sh "$KERNEL_LAST_TIME" exit $? diff --git a/test-case/check-ipc-flood.sh b/test-case/check-ipc-flood.sh index 3a9a3738..5095fbf9 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_time func_lib_check_sudo dlogi "Check sof debug fs environment" @@ -56,5 +56,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_TIME" exit 0 diff --git a/test-case/check-kmod-load-unload.sh b/test-case/check-kmod-load-unload.sh index ba2853db..20d330e0 100755 --- a/test-case/check-kmod-load-unload.sh +++ b/test-case/check-kmod-load-unload.sh @@ -30,7 +30,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_time loop_cnt=${OPT_VALUE_lst['l']} usb_audio_module="snd_usb_audio" @@ -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_time # After module removal, it takes about 10s for "aplay -l" to show # device list, within this 10s, it shows "no soundcard found". Here @@ -77,13 +77,13 @@ 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_TIME" if [[ $? -ne 0 ]]; then dloge "error found after kmod unload is real error, failing" exit 1 fi - func_lib_setup_kernel_last_line + func_lib_setup_kernel_last_time dlogi "run kmod/sof_insert.sh" sudo sof_insert.sh [[ $? -ne 0 ]] && dloge "insert modules error" && exit @@ -91,7 +91,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_TIME" if [[ $? -ne 0 ]]; then dloge "Found error(s) in kernel log after module insertion" exit 1 diff --git a/test-case/check-pause-release-suspend-resume.sh b/test-case/check-pause-release-suspend-resume.sh index 0ccf1b90..00c90b43 100755 --- a/test-case/check-pause-release-suspend-resume.sh +++ b/test-case/check-pause-release-suspend-resume.sh @@ -109,7 +109,7 @@ esac [[ ${OPT_VALUE_lst['s']} -eq 1 ]] && func_lib_start_log_collect -func_lib_setup_kernel_last_line +func_lib_setup_kernel_last_time 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" @@ -179,5 +179,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_TIME" exit $? diff --git a/test-case/check-pause-resume.sh b/test-case/check-pause-resume.sh index e31166b1..ce7c1d4f 100755 --- a/test-case/check-pause-resume.sh +++ b/test-case/check-pause-resume.sh @@ -74,7 +74,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_time for idx in $(seq 0 $(expr $PIPELINE_COUNT - 1)) do channel=$(func_pipeline_parse_value $idx channel) @@ -127,5 +127,5 @@ END } done -sof-kernel-log-check.sh $KERNEL_LAST_LINE +sof-kernel-log-check.sh "$KERNEL_LAST_TIME" exit $? diff --git a/test-case/check-playback.sh b/test-case/check-playback.sh index 7d26ebb8..103214d7 100755 --- a/test-case/check-playback.sh +++ b/test-case/check-playback.sh @@ -64,7 +64,7 @@ else dlogi "using $file as playback source" fi -func_lib_setup_kernel_last_line +func_lib_setup_kernel_last_time func_lib_check_sudo func_pipeline_export $tplg "type:playback & ${OPT_VALUE_lst['S']}" @@ -102,5 +102,5 @@ do done done -sof-kernel-log-check.sh $KERNEL_LAST_LINE +sof-kernel-log-check.sh "$KERNEL_LAST_TIME" exit $? diff --git a/test-case/check-runtime-pm-double-active.sh b/test-case/check-runtime-pm-double-active.sh index e8e034b1..39a0d966 100755 --- a/test-case/check-runtime-pm-double-active.sh +++ b/test-case/check-runtime-pm-double-active.sh @@ -72,7 +72,7 @@ DEV_LST['capture']='/dev/null' [[ ${OPT_VALUE_lst['s']} -eq 1 ]] && func_lib_start_log_collect func_pipeline_export $tplg -func_lib_setup_kernel_last_line +func_lib_setup_kernel_last_time for idx in $(seq 0 $(expr $PIPELINE_COUNT - 1)) do @@ -146,5 +146,5 @@ do } done -sof-kernel-log-check.sh $KERNEL_LAST_LINE +sof-kernel-log-check.sh "$KERNEL_LAST_TIME" exit $? diff --git a/test-case/check-runtime-pm-status.sh b/test-case/check-runtime-pm-status.sh index 043b4761..f0d1d5da 100755 --- a/test-case/check-runtime-pm-status.sh +++ b/test-case/check-runtime-pm-status.sh @@ -66,7 +66,7 @@ DEV_LST['capture']='/dev/null' [[ ${OPT_VALUE_lst['s']} -eq 1 ]] && func_lib_start_log_collect func_pipeline_export $tplg -func_lib_setup_kernel_last_line +func_lib_setup_kernel_last_time for idx in $(seq 0 $(expr $PIPELINE_COUNT - 1)) do @@ -132,5 +132,5 @@ do } done -sof-kernel-log-check.sh $KERNEL_LAST_LINE +sof-kernel-log-check.sh "$KERNEL_LAST_TIME" exit $? diff --git a/test-case/check-signal-stop-start.sh b/test-case/check-signal-stop-start.sh index d156ef3f..3177750e 100755 --- a/test-case/check-signal-stop-start.sh +++ b/test-case/check-signal-stop-start.sh @@ -57,7 +57,7 @@ case $test_mode in ;; esac -func_lib_setup_kernel_last_line +func_lib_setup_kernel_last_time func_stop_start_pipeline() { @@ -118,5 +118,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_TIME" exit $? diff --git a/test-case/check-suspend-resume-with-audio.sh b/test-case/check-suspend-resume-with-audio.sh index 73672fe3..3d3b7cd8 100755 --- a/test-case/check-suspend-resume-with-audio.sh +++ b/test-case/check-suspend-resume-with-audio.sh @@ -51,7 +51,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_time tplg=${OPT_VALUE_lst['t']} [[ ${OPT_VALUE_lst['s']} -eq 1 ]] && func_lib_start_log_collect @@ -129,5 +129,5 @@ do done # check full log -sof-kernel-log-check.sh $KERNEL_LAST_LINE +sof-kernel-log-check.sh "$KERNEL_LAST_TIME" exit $? diff --git a/test-case/check-suspend-resume.sh b/test-case/check-suspend-resume.sh index 70dedbea..1942e467 100755 --- a/test-case/check-suspend-resume.sh +++ b/test-case/check-suspend-resume.sh @@ -39,7 +39,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_time 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_TIME" exit $? diff --git a/test-case/check-xrun-injection.sh b/test-case/check-xrun-injection.sh index de7a9b12..9d03b73d 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_time func_lib_check_sudo func_pipeline_export $tplg "type:playback,capture" @@ -125,5 +125,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_TIME" exit $? diff --git a/test-case/multiple-pause-resume.sh b/test-case/multiple-pause-resume.sh index 90750e1d..1592592c 100755 --- a/test-case/multiple-pause-resume.sh +++ b/test-case/multiple-pause-resume.sh @@ -56,7 +56,7 @@ func_pipeline_export $tplg [[ ${OPT_VALUE_lst['s']} -eq 1 ]] && func_lib_start_log_collect -func_lib_setup_kernel_last_line +func_lib_setup_kernel_last_time declare -a pipeline_idx_lst declare -a cmd_idx_lst @@ -191,5 +191,5 @@ do } done -sof-kernel-log-check.sh $KERNEL_LAST_LINE +sof-kernel-log-check.sh "$KERNEL_LAST_TIME" exit $? diff --git a/test-case/multiple-pipeline-capture.sh b/test-case/multiple-pipeline-capture.sh index 06ba6b68..ded7c903 100755 --- a/test-case/multiple-pipeline-capture.sh +++ b/test-case/multiple-pipeline-capture.sh @@ -51,7 +51,7 @@ func_pipeline_export $tplg max_count=0 # 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_time # now small function define declare -A APP_LST DEV_LST @@ -156,5 +156,5 @@ do } done -sof-kernel-log-check.sh $KERNEL_LAST_LINE >/dev/null +sof-kernel-log-check.sh "$KERNEL_LAST_TIME" >/dev/null exit $? diff --git a/test-case/multiple-pipeline-playback.sh b/test-case/multiple-pipeline-playback.sh index 30482f59..ccbb5438 100755 --- a/test-case/multiple-pipeline-playback.sh +++ b/test-case/multiple-pipeline-playback.sh @@ -51,7 +51,7 @@ func_pipeline_export $tplg max_count=0 # 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_time # now small function define declare -A APP_LST DEV_LST @@ -156,5 +156,5 @@ do } done -sof-kernel-log-check.sh $KERNEL_LAST_LINE >/dev/null +sof-kernel-log-check.sh "$KERNEL_LAST_TIME" >/dev/null exit $? diff --git a/test-case/simultaneous-playback-capture.sh b/test-case/simultaneous-playback-capture.sh index a4698577..c660ef54 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_time func_error_exit() { @@ -117,5 +117,5 @@ do } done -sof-kernel-log-check.sh $KERNEL_LAST_LINE > /dev/null +sof-kernel-log-check.sh "$KERNEL_LAST_TIME" > /dev/null exit $? diff --git a/test-case/test-speaker.sh b/test-case/test-speaker.sh index 9d2a87de..8a703f96 100755 --- a/test-case/test-speaker.sh +++ b/test-case/test-speaker.sh @@ -30,7 +30,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_time for idx in $(seq 0 $(expr $PIPELINE_COUNT - 1)) do channel=$(func_pipeline_parse_value $idx channel) @@ -53,5 +53,5 @@ do fi done -sof-kernel-log-check.sh $KERNEL_LAST_LINE +sof-kernel-log-check.sh "$KERNEL_LAST_TIME" exit $? diff --git a/test-case/volume-basic-test.sh b/test-case/volume-basic-test.sh index 898e8269..08bddeaf 100755 --- a/test-case/volume-basic-test.sh +++ b/test-case/volume-basic-test.sh @@ -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_TIME" [[ $? -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 28bd356e..af800d5a 100755 --- a/tools/sof-kernel-log-check.sh +++ b/tools/sof-kernel-log-check.sh @@ -1,34 +1,36 @@ #!/bin/bash -begin_line=${1:-1} +begin_time=${1:-0} declare err_str ignore_str project_key err_str="error|failed|timed out|panic|oops" ignore_str="error: debugfs write failed to idle -16|error: status|iteration [01]" project_key="sof-audio" -[[ ! "$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="sed -n '$begin_line,\$p' /var/log/kern.log" +[[ ! "$err_str" ]] && { + echo "Missing error keyword list" + builtin exit 0 +} -# 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="sed -n '$begin_line,\$p' /var/log/kern.log" - -#echo "run $0 with parameter '$*' for check kernel message error" +if [ "X$begin_time" == "X0" ]; then + cmd="dmesg" +else + date -d "$begin_time" +'%F %T' > /dev/null || { + echo "Error parameter for date: $begin_time" + echo "Support date format: date +'%F %T'" + builtin exit 0 + } + journalctl --flush + cmd="journalctl --dmesg --no-pager --no-hostname -o short-precise --since='$begin_time'" +fi if [ "$ignore_str" ]; then - err=$(eval $cmd|grep 'Call Trace' -A5 -B3)$(eval $cmd | grep $project_key | grep -E "$err_str"|grep -vE "$ignore_str") + err=$(eval "$cmd"|grep 'Call Trace' -A5 -B3)$(eval "$cmd" | grep $project_key | grep -E "$err_str"|grep -vE "$ignore_str") else - err=$(eval $cmd|grep 'Call Trace' -A5 -B3)$(eval $cmd | grep $project_key | grep -E "$err_str") + err=$(eval "$cmd"|grep 'Call Trace' -A5 -B3)$(eval "$cmd" | grep $project_key | grep -E "$err_str") fi if [ "$err" ]; then - echo `date -u '+%Y-%m-%d %T %Z'` "[ERROR]" "Caught dmesg error" + echo "$(date -u '+%F %T %Z') [ERROR] Caught dmesg error" echo "===========================>>" echo "$err" echo "<<===========================" From 1a1257cda29dd070e6e63812f56780f065942703 Mon Sep 17 00:00:00 2001 From: "Wu, BinX" Date: Wed, 6 May 2020 22:51:50 +0800 Subject: [PATCH 4/4] lib: hijack: use journalctl command to dump kernel information use journalctl instead of catch information from /var/log/kern.log file 1. DMESG_LOG_START_LINE => CASE_KERNEL_START_TIME 2. with this change, sof-get-kernel-line is not useful, remove it Signed-off-by: Wu, BinX --- README.md | 4 ---- case-lib/hijack.sh | 12 ++++-------- case-lib/lib.sh | 10 +++++----- test-case/check-reboot.sh | 4 ++-- test-case/check-sof-logger.sh | 4 ++-- test-case/verify-kernel-module-load-probe.sh | 4 ++-- test-case/verify-pcm-list.sh | 4 ++-- test-case/verify-sof-firmware-load.sh | 3 +-- tools/sof-get-kernel-line.sh | 12 ------------ 9 files changed, 18 insertions(+), 39 deletions(-) delete mode 100755 tools/sof-get-kernel-line.sh diff --git a/README.md b/README.md index d859e0fa..62cb8b3f 100644 --- a/README.md +++ b/README.md @@ -108,10 +108,6 @@ apl * sof-get-default-tplg.sh
Load the tplg file name from system log which is recorded from system bootup -* sof-get-kernel-line.sh -
Print all kernel versions and their line numbers from /var/log/kern.log, - with the most recent - * sof-kernel-dump.sh
Catch all kernel information after system boot up by `journalctl` command diff --git a/case-lib/hijack.sh b/case-lib/hijack.sh index eea7d82f..4053f215 100644 --- a/case-lib/hijack.sh +++ b/case-lib/hijack.sh @@ -20,15 +20,11 @@ function func_exit_handler() sleep 1s 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 [[ -n "$CASE_KERNEL_START_TIME" ]]; then + journalctl --flush + journalctl --dmesg --no-pager --no-hostname -o short-precise --since="$CASE_KERNEL_START_TIME" > "$LOG_ROOT/dmesg.txt" else - cut -f5- -d ' ' /var/log/kern.log > "$LOG_ROOT/dmesg.txt" + journalctl --dmesg --no-pager --no-hostname -o short-precise > "$LOG_ROOT/dmesg.txt" fi # get ps command result as list diff --git a/case-lib/lib.sh b/case-lib/lib.sh index 3942fe60..968bc990 100644 --- a/case-lib/lib.sh +++ b/case-lib/lib.sh @@ -193,9 +193,9 @@ func_lib_get_tplg_path() return 0 } -# force ask buffer data write into file system -sudo sync -f -# 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;}') +journalctl --flush +if [ ! "$CASE_KERNEL_START_TIME" ]; then + # format time stamp output for journalctl command + func_lib_setup_kernel_last_time + CASE_KERNEL_START_TIME="$KERNEL_LAST_TIME" fi diff --git a/test-case/check-reboot.sh b/test-case/check-reboot.sh index 02ef5166..0dbec78e 100755 --- a/test-case/check-reboot.sh +++ b/test-case/check-reboot.sh @@ -144,14 +144,14 @@ sudo chown $UID $boot_file old_content="$(cat $boot_file|grep -v '^exit')" # write the information to /etc/rc.local # LOG_ROOT to make sure all tests, including sub-cases, write log to the same target folder -# DMESG_LOG_START_LINE to just keep last kernel bootup log +# CASE_KERNEL_START_TIME to just keep last kernel bootup log boot_once_flag=$(realpath $(which sof-boot-once.sh)) cat << END > $boot_file $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;}') +export CASE_KERNEL_START_TIME='$(journalctl --dmesg --no-pager -n 1 |head -n 1|awk '{print $(NF-3)" "$(NF-2);}')' bash -c '$full_cmd' exit 0 diff --git a/test-case/check-sof-logger.sh b/test-case/check-sof-logger.sh index e8fdc9b9..d5312ad5 100755 --- a/test-case/check-sof-logger.sh +++ b/test-case/check-sof-logger.sh @@ -21,8 +21,8 @@ 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;}') +# hijack CASE_KERNEL_START_TIME which refer dump kernel log in exit function +unset CASE_KERNEL_START_TIME # check sof-logger location if [ -z $(which sof-logger) ]; then diff --git a/test-case/verify-kernel-module-load-probe.sh b/test-case/verify-kernel-module-load-probe.sh index 9bec1143..722bc652 100755 --- a/test-case/verify-kernel-module-load-probe.sh +++ b/test-case/verify-kernel-module-load-probe.sh @@ -15,8 +15,8 @@ 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;}') +# hijack CASE_KERNEL_START_TIME which refer dump kernel log in exit function +unset CASE_KERNEL_START_TIME 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 356c9ce1..34456d00 100755 --- a/test-case/verify-pcm-list.sh +++ b/test-case/verify-pcm-list.sh @@ -26,8 +26,8 @@ tplg=${OPT_VALUE_lst['t']} tplg_path=`func_lib_get_tplg_path "$tplg"` [[ "$?" != "0" ]] && dloge "No available topology for this test case" && exit 1 -# 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;}') +# hijack CASE_KERNEL_START_TIME which refer dump kernel log in exit function +unset CASE_KERNEL_START_TIME 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 6af6009d..45bd1130 100755 --- a/test-case/verify-sof-firmware-load.sh +++ b/test-case/verify-sof-firmware-load.sh @@ -22,8 +22,7 @@ if alias |grep -q 'Sub-Test' ;then cmd="dmesg" else # hijack CASE_KERNEL_START_TIME which refer dump kernel log in exit function - # shellcheck disable=SC2034 - DMESG_LOG_START_LINE=$(sof-get-kernel-line.sh|tail -n 1 |awk '{print $1;}') + unset CASE_KERNEL_START_TIME cmd="sof-kernel-dump.sh" fi diff --git a/tools/sof-get-kernel-line.sh b/tools/sof-get-kernel-line.sh deleted file mode 100755 index ad4d599d..00000000 --- a/tools/sof-get-kernel-line.sh +++ /dev/null @@ -1,12 +0,0 @@ -#!/bin/bash - -# dump line number + kernel version -# for example: -# 22 4.15.0-74-generic -# 1092 4.15.0-74-generic -# 2156 4.15.0-74-generic -# 3246 4.15.0-74-generic -log_file=${1:-"/var/log/kern.log"} -[[ ! -f "$log_file" ]] && builtin exit 1 -bootup_keyword='\[ 0.000000\] Linux version ' -grep -na "$bootup_keyword" "$log_file"|sed 's/\x0//g'|awk -F ':' '{print $1 $(NF-2);}'|sed "s/$bootup_keyword//g"|awk '{print $1, $2;}'