Skip to content
Closed
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
6 changes: 1 addition & 5 deletions README.md
Original file line number Diff line number Diff line change
Expand Up @@ -108,12 +108,8 @@ apl
* sof-get-default-tplg.sh
<br> Load the tplg file name from system log which is recorded from system bootup

* sof-get-kernel-line.sh
<br> Print all kernel versions and their line numbers from /var/log/kern.log,
with the most recent <first/last>

* sof-kernel-dump.sh
<br> Catch all kernel information after system boot up from /var/log/kern.log file
<br> Catch all kernel information after system boot up by `journalctl` command

* sof-kernel-log-check.sh
<br> Check dmesg for errors and ensure that any found are real errors
Expand Down
5 changes: 0 additions & 5 deletions case-lib/config.sh
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
12 changes: 4 additions & 8 deletions case-lib/hijack.sh
Original file line number Diff line number Diff line change
Expand Up @@ -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
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Please explain in a comment when CASE_KERNEL_START_TIME is missing and why.

journalctl --flush
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why --flush here?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

just use to confirm data already store, so I can remove it?

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

journalctl --flush can help only if there is a system crash soon. If don't expect a crash between this line and the next line, do you?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

when we load this part at exit, so it seems don't need line

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"
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Please put --no-pager --no-hostname -o short-precise into a new JOURNALCTL_FORMAT_OPTS variable so they can be modified in one place.

fi

# get ps command result as list
Expand Down
16 changes: 9 additions & 7 deletions case-lib/lib.sh
Original file line number Diff line number Diff line change
Expand Up @@ -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()
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This does not return the "last" time, this returns the boot time?!

"last line" was the last line in kern.log, I understand that.

I don't understand what "last time" could mean.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

As test step, we don't want check full kernel log,
we just want check the kernel from what to current

older code is for /var/log/kern.log, so it is kernel log last line
current is journalctl, so it is kern.log last time stamp

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

So still use kernel_last_line will more easy to understand?

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

OK, I think I understand now.

When using time, you don't have to care about lines any more (that confused me a bit). Instead you can just do this:

set_test_start_time()
{
  test_start_epoch=$(date +%s)
}

# test runs ...
journalctl --since="$test_start_epoch" $JOURNACTL_FORMAT_OPTS ...

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I know date +%s, in test process, I find catch from journalctl -o short-iso-precise
for each case is more precise, because our component will write more long in 1s

{
# 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/ }
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Discarding the timezone is dangerous. It will cause bugs at least once per year when daylight savings. Use date +%s and UTC time in all internal variables (not in display)

}

SOF_LOG_COLLECT=0
Expand Down Expand Up @@ -191,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
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

sync -f was needed because you read from the filesystem. journalctl doesn't read from the filesystem.

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
4 changes: 2 additions & 2 deletions test-case/check-capture.sh
Original file line number Diff line number Diff line change
Expand Up @@ -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']}"

Expand Down Expand Up @@ -104,5 +104,5 @@ do
done
done

sof-kernel-log-check.sh $KERNEL_LAST_LINE
sof-kernel-log-check.sh "$KERNEL_LAST_TIME"
exit $?
4 changes: 2 additions & 2 deletions test-case/check-ipc-flood.sh
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand All @@ -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
10 changes: 5 additions & 5 deletions test-case/check-kmod-load-unload.sh
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand All @@ -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
Expand Down Expand Up @@ -77,21 +77,21 @@ 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
sleep 1

## - 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
Expand Down
4 changes: 2 additions & 2 deletions test-case/check-pause-release-suspend-resume.sh
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand Down Expand Up @@ -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 $?
4 changes: 2 additions & 2 deletions test-case/check-pause-resume.sh
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down Expand Up @@ -127,5 +127,5 @@ END
}
done

sof-kernel-log-check.sh $KERNEL_LAST_LINE
sof-kernel-log-check.sh "$KERNEL_LAST_TIME"
exit $?
4 changes: 2 additions & 2 deletions test-case/check-playback.sh
Original file line number Diff line number Diff line change
Expand Up @@ -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']}"

Expand Down Expand Up @@ -102,5 +102,5 @@ do
done
done

sof-kernel-log-check.sh $KERNEL_LAST_LINE
sof-kernel-log-check.sh "$KERNEL_LAST_TIME"
exit $?
4 changes: 2 additions & 2 deletions test-case/check-reboot.sh
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
4 changes: 2 additions & 2 deletions test-case/check-runtime-pm-double-active.sh
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -146,5 +146,5 @@ do
}
done

sof-kernel-log-check.sh $KERNEL_LAST_LINE
sof-kernel-log-check.sh "$KERNEL_LAST_TIME"
exit $?
4 changes: 2 additions & 2 deletions test-case/check-runtime-pm-status.sh
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -132,5 +132,5 @@ do
}
done

sof-kernel-log-check.sh $KERNEL_LAST_LINE
sof-kernel-log-check.sh "$KERNEL_LAST_TIME"
exit $?
4 changes: 2 additions & 2 deletions test-case/check-signal-stop-start.sh
Original file line number Diff line number Diff line change
Expand Up @@ -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()
{
Expand Down Expand Up @@ -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 $?
4 changes: 2 additions & 2 deletions test-case/check-sof-logger.sh
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
4 changes: 2 additions & 2 deletions test-case/check-suspend-resume-with-audio.sh
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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 $?
4 changes: 2 additions & 2 deletions test-case/check-suspend-resume.sh
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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 $?
4 changes: 2 additions & 2 deletions test-case/check-xrun-injection.sh
Original file line number Diff line number Diff line change
Expand Up @@ -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"

Expand Down Expand Up @@ -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 $?
4 changes: 2 additions & 2 deletions test-case/multiple-pause-resume.sh
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -191,5 +191,5 @@ do
}
done

sof-kernel-log-check.sh $KERNEL_LAST_LINE
sof-kernel-log-check.sh "$KERNEL_LAST_TIME"
exit $?
4 changes: 2 additions & 2 deletions test-case/multiple-pipeline-capture.sh
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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 $?
4 changes: 2 additions & 2 deletions test-case/multiple-pipeline-playback.sh
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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 $?
4 changes: 2 additions & 2 deletions test-case/simultaneous-playback-capture.sh
Original file line number Diff line number Diff line change
Expand Up @@ -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()
{
Expand Down Expand Up @@ -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 $?
Loading