From 2d0917e48ae4047b6edc592a9844424ee56007fc Mon Sep 17 00:00:00 2001 From: Marc Herbert Date: Tue, 9 Jul 2024 14:37:23 -0700 Subject: [PATCH 1/5] multiple-pause-resume.sh: add $TOPDIR variable So we can easily find other tools. Signed-off-by: Marc Herbert --- test-case/multiple-pause-resume.sh | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/test-case/multiple-pause-resume.sh b/test-case/multiple-pause-resume.sh index f7ee8a48..b5268d5d 100755 --- a/test-case/multiple-pause-resume.sh +++ b/test-case/multiple-pause-resume.sh @@ -20,8 +20,9 @@ set -e ## no errors occur for either process ## +TOPDIR=$(cd "$(dirname "${BASH_SOURCE[0]}")"/.. && pwd) # shellcheck source=case-lib/lib.sh -source "$(dirname "${BASH_SOURCE[0]}")"/../case-lib/lib.sh +source "$TOPDIR"/case-lib/lib.sh OPT_NAME['t']='tplg' OPT_DESC['t']="tplg file, default value is env TPLG: $TPLG" OPT_HAS_ARG['t']=1 OPT_VAL['t']="$TPLG" From 33817e914955909abf63b01a2c52ba5bdf2506a8 Mon Sep 17 00:00:00 2001 From: Marc Herbert Date: Tue, 9 Jul 2024 14:37:23 -0700 Subject: [PATCH 2/5] check-pause-resume.sh: add $TOPDIR variable So we can invoke other tools easily. Signed-off-by: Marc Herbert --- test-case/check-pause-resume.sh | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/test-case/check-pause-resume.sh b/test-case/check-pause-resume.sh index 1d5b8153..6819cf04 100755 --- a/test-case/check-pause-resume.sh +++ b/test-case/check-pause-resume.sh @@ -17,8 +17,9 @@ set -e ## no error happen for aplay/arecord ## +TOPDIR=$(cd "$(dirname "${BASH_SOURCE[0]}")"/.. && pwd) # shellcheck source=case-lib/lib.sh -source "$(dirname "${BASH_SOURCE[0]}")"/../case-lib/lib.sh +source "$TOPDIR"/case-lib/lib.sh OPT_NAME['t']='tplg' OPT_DESC['t']='tplg file, default value is env TPLG: $''TPLG' OPT_HAS_ARG['t']=1 OPT_VAL['t']="$TPLG" From 8ba9b236c0e1a00d5f39e1b1bc45d6e982099873 Mon Sep 17 00:00:00 2001 From: Marc Herbert Date: Tue, 9 Jul 2024 14:37:23 -0700 Subject: [PATCH 3/5] Add new Expect script `tools/apause.exp` This all started as an effort to solve test failures caused by "MAX" volume. See #931 and others linked from there for more context. Another obvious issue was the duplication of `expect` code across two tests (check-pause-resume.sh and multiple-pause-resume.sh) After a bit of time actually "testing the tests" I realized the original author did not really understand `expect` or the problem. So I rewrote the entire `expect` part. The list of previous issues is a bit too long not to forget any but here are some: - The script could get "out of sync" with aplay and report that it was paused when it was actually resumed! And vice-versa. - De-duplication; obviously. - Moving to a separate script also solves the following problems: - Can be invoked, tested and debugged separately outside any shell script - Simplifies quoting - Unlocks editor features like syntax checking - Proper understanding and handling of newlines. - The expect script does not "sleep" anymore, which stops backpressuring and blocking the console output from aplay - with unknown side effects! - Adding `log_user 0` makes the test logs readable at last - Add decent logging for easier maintenance - Logging timestamps demonstrate that the entire aproach is too slow for pause/resume cycles shorter than ~200 ms. Default values won't be changed yet but at least the problem is now obvious. - Handle "MAX" volume! Not an error yet because it happens really across the board (MAX does usualy not happen long enough to timeout and _fail_ across the board) but the code is ready to upgrade the "MAX" warning to an ERROR with a one-line change. - Report EOF and timeouts differently. - Probably others. Signed-off-by: Marc Herbert --- case-lib/apause.exp | 274 ++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 274 insertions(+) create mode 100755 case-lib/apause.exp diff --git a/case-lib/apause.exp b/case-lib/apause.exp new file mode 100755 index 00000000..ec2178d1 --- /dev/null +++ b/case-lib/apause.exp @@ -0,0 +1,274 @@ +#!/usr/bin/env expect + +# If you're new to expect: +# +# - Expect is "only" a Tcl extension and Tcl command. +# An "expect script" is a somewhat misleading shorthand for "a Tcl +# script that happens to use expect/" +# +# - So, you can't understand this script (or any expect script) without +# some minimum Tcl knowledge. Especially: strings, quoting, lists and +# delayed evaluations. +# +# - Expect resources on the Internet are hit-and-miss. Don Libes' book +# "Exploring Expect" is great: buy the book or check whether your +# employer has an online subscription. That book has a really nice and +# short (single chapter) Tcl introduction too. +# Tcl resources on the Internet are much better and expect resources. +# +# - The man pages are not good for learning but they are a very useful +# references: run `apt install tcl8*-doc` or equivalent to get Tcl man +# pages, then: `man [3tcl] expect`, `man [3tcl] after`, etc. +# +# - Use the interactive `rlwrap tclsh` to experiment. +# + +# log level: 0 = initialization, warnings and errors only, 1 = normal, 2+ = debug +set log_level 1 + +# Set to 1 only when you're desperate: this randomly interleaves +# aplay's output with output from this script. +log_user 0 + +# aplay -vv is chatty: no need to wait for very long +set timeout 5 + +proc log {lvl msg} { + global log_level cmd_shortname + if {$lvl <= $log_level} { + puts "t=[rel_time_ms] ms: $cmd_shortname: $msg" + } +} + +# Pop the first element of the list argument. +# Equivalent to "shift" in shell. +proc lshift {args} { + # "upvar" required to escape scope and change argument in place + upvar $args args_up + set first [lindex $args_up 0] + set args_up [lreplace $args_up 0 0] + return $first +} + +# Random numbers between min and min+range +proc rand_min_range {min range} { + return [expr $min + int([expr rand() * $range])] +} + +set cmd_shortname [lshift argv] +set repeat_count [lshift argv] +set rnd_min [lshift argv] +set rnd_range [lshift argv] + +# Should really be 200 ms because of the round-trip between pressing +# "space" and aplay's acknowledgement + other various delays everywhere. +# Keep it that small for now for backwards compatibility. +if {$rnd_min < 20} { + puts "$argv0 ERROR: rnd_min=$rnd_min argument is lower than 100ms" + exit 1 +} + +# How many times we paused +set pauses_counter 0 + +# Logging needs this early. Will reset better later. +set start_time_ms [clock milliseconds] + +proc rel_time_ms {} { + global start_time_ms + return [expr [clock milliseconds] - $start_time_ms] +} + +proc press_space {} { + global last_space_time + log 2 "Pressing SPACE" + send " " + set last_space_time [rel_time_ms] + log 3 "last_space_time set to $last_space_time" +} + +proc substract_time_since_last_space {duration} { + global last_space_time + set _delay [expr $duration - ([rel_time_ms] - $last_space_time)] + # Don't return negative values if we already passed the deadline. + # Don't return zero either to avoid interrupting ourselves (just in + # case Tcl thought it would be a good idea) + return [tcl::mathfunc::max 1 $_delay] +} + +# aplay's VU-meter uses CRs to write over itself and avoid terminal scrolling. +# But when debugging we want to see everything. +proc cr_to_lf {arg} { + set _lf [regsub "\r" $arg "\n"] + return [string trim $_lf] +} + +# Use all remaining arguments as the command to invoke. Example: +# +# arecord $cmd_opts -D $dev -r $rate -c $channel -f $fmt -vv -i $file_name ... +log 0 "$argv0 spawning: $argv" +spawn {*}$argv +set start_time_ms [clock milliseconds]; # re-adjust +set last_space_time 0 ; # could not resist that name + +# states: recording, pause_requested, paused, recording_requested +set state recording_requested + +set in_max_burst false +set volume_always_zero true + +# Key `expect` matching facts to keep in mind: +# +# 1. `expect` never cares about newlines on its own. You must use `\r` +# and/or `\n` _everywhere_ you care about newlines. +# +# 2. When to use \r versus \n versus \r\n (CRLF) in expect unfortunately +# requires some tty _and_ arecord VU-meter knowledge and is a bit too +# complicated to be summarized here. +# +# 3. When nothing matches, expect keeps reading and keeps looking +# forward. As soon as something matches, `expect` _ignores_ what did +# not match earlier. Except when using ^ which is the "start of +# input" anchor (NOT a "start of line" anchor) +# +# 4. Conversely, whatever is left AFTER a match will always be submitted +# for matching again: exactly like it has not arrived yet (otherwise it +# would be always racy). + +expect { + + # When multiple patterns match, first pattern wins. + + # Volume xx% or MAX line + # + # When not backpressured by a sleeping (=bad!) expect, + # aplay seems to update its VU-meter about once every 100ms. + -re {#[^\r\n]*\| (..*%|MAX)\r} { + + # - $expect_out(0,string) = match + # - $expect_out(buffer) = everything before match + match + + set buffer_with_lf "[cr_to_lf $expect_out(buffer)]" + + # Always print the audio stream configuration preamble + if [regexp {PCM card} "$buffer_with_lf"] { + log 0 "$buffer_with_lf" + } + + if [regexp {\| MAX} "$buffer_with_lf"] { + if { ! $in_max_burst } { + # TODO: upgrade this to a failure once all ALSA settings have been fixed. + log 0 "WARNING: volume MAX! Bug or bad ALSA settings?" + log 0 "$buffer_with_lf" + set in_max_burst true + } + } else { + set in_max_burst false + } + + if $volume_always_zero { + # This is not perfect because if `expect` becomes very slow + # for some unknown reason, then there could be _multiple_ + # volume lines in a single of these buffer iterations and then we + # could miss some non-zeros. + # This is very unlikely though so this is statically good enough. + if {! [regexp {\| ( |0)0%} "$buffer_with_lf"]} { + set volume_always_zero false + } + } + + switch $state { + + recording { + log 2 "Recording volume #... | xx%:\n[cr_to_lf $expect_out(buffer)]" + exp_continue + } + + pause_requested { + log 2 "Volume #... | xx% left after requesting pause:\n[cr_to_lf $expect_out(buffer)]" + exp_continue + } + + paused { + log 0 "ERROR: found VOLUME while paused!" + log 0 "$buffer_with_lf" + exit 1 + } + + recording_requested { + # First volume line printed since unpaused; recording successfully started! + set state recording + + set _record_for [rand_min_range $rnd_min $rnd_range] + log 1 "($pauses_counter/$repeat_count) Found volume ### | xx%, recording for $_record_for ms" + + set _delay [substract_time_since_last_space $_record_for] + after $_delay "press_space; set state pause_requested" + log 3 "last_space_time=$last_space_time; timer in $_delay" + + # Debug matched string + log 2 "$buffer_with_lf" + exp_continue + } + + default { + log 0 "ERROR: unexpected state=$state! Volume is:\n[cr_to_lf $expect_out(buffer)]" + exit 1 + } + + } + + } + + {=== PAUSE ===} { + if {$state != "pause_requested"} { + # TODO: upgrade this to an ERROR? + log 0 "WARNING: received == PAUSE == while in state $state! Ignoring." + exp_continue + } + + set state paused + # Re-enable the MAX warning + set in_max_burst false + + set _pausing_for [rand_min_range $rnd_min $rnd_range] + log 1 "($pauses_counter/$repeat_count) Found === PAUSE === , pausing for $_pausing_for ms" + + set _delay [substract_time_since_last_space $_pausing_for] + after $_delay "press_space; set state recording_requested" + log 3 "last_space_time=$last_space_time; timer in $_delay" + + + incr pauses_counter + if { $pauses_counter <= $repeat_count } { + exp_continue + } + # Normal exit of the "expect" command here + } + + # This overlaps with the main volume case above but it's very useful logging when + # forgetting to pass a double -vv and timing out + -re {PCM card[^#]*} { + log 0 "Preamble:\n$expect_out(buffer)" + exp_continue + } + + timeout { + log 0 "ERROR: $argv0 timed out. Did you use -vv?" + exit 1 + } + + eof { + log 0 "ERROR: $argv0: EOF." + log 0 "$expect_out(buffer)" + exit 1 + } +} + +if $volume_always_zero { + log 0 "WARNING: volume was always 00%!" +} + +# TODO: collect exit status with explicit exp_close + exp_wait? + +log 0 "SUCCESS: $argv0 $argv" From 5ebbf0cbeb978163c545db8686f36587680ba652 Mon Sep 17 00:00:00 2001 From: Marc Herbert Date: Tue, 9 Jul 2024 14:37:23 -0700 Subject: [PATCH 4/5] multiple-pause-resume.sh: switch to new `apause.exp` script See long commit message in previous commit adding apause.exp Signed-off-by: Marc Herbert --- test-case/multiple-pause-resume.sh | 33 ++++++++---------------------- 1 file changed, 9 insertions(+), 24 deletions(-) diff --git a/test-case/multiple-pause-resume.sh b/test-case/multiple-pause-resume.sh index b5268d5d..0df264a4 100755 --- a/test-case/multiple-pause-resume.sh +++ b/test-case/multiple-pause-resume.sh @@ -121,30 +121,12 @@ func_pause_resume_pipeline() # expr rand(): produces random numbers between 0 and 1 # after ms: Ms must be an integer giving a time in milliseconds. # The command sleeps for ms milliseconds and then returns. - dlogi "$pcm to command: $cmd -D $dev -r $rate -c $channel -f $fmt -vv -i $file -q" - expect < $repeat_count } { exit 0 } - exp_continue - } -} -exit 1 -END + + local shortname="cmd$idx $cmd $pcm" + + dlogi "Starting: apause.exp $cmd -D $dev -r $rate -c $channel -f $fmt -vv -i $file &" + "$TOPDIR"/case-lib/apause.exp "$shortname" "$repeat_count" "$rnd_min" "$rnd_range" \ + "$cmd" -D "$dev" -r "$rate" -c "$channel" -f "$fmt" -vv -i "$file" & } # to prevent infinite loop, 5 second per a repeat is plenty @@ -163,6 +145,9 @@ do do func_pause_resume_pipeline "$idx" pid_lst=("${pid_lst[@]}" $!) + # Stagger a bit to avoid preambles interleaved with each other. + # It's very far from perfect but it helps a little bit. + sleep 0.1 done # wait for expect script finished dlogi "wait for expect process finished" From cfb796e8f9e2b10a7ef93f3601d7d524197b216d Mon Sep 17 00:00:00 2001 From: Marc Herbert Date: Tue, 9 Jul 2024 14:37:24 -0700 Subject: [PATCH 5/5] check-pause-resume.sh: switch to new `apause.exp` script See long commit message in previous commit adding apause.exp Signed-off-by: Marc Herbert --- test-case/check-pause-resume.sh | 41 ++++++++------------------------- 1 file changed, 10 insertions(+), 31 deletions(-) diff --git a/test-case/check-pause-resume.sh b/test-case/check-pause-resume.sh index 6819cf04..17c49ffc 100755 --- a/test-case/check-pause-resume.sh +++ b/test-case/check-pause-resume.sh @@ -93,40 +93,19 @@ do dev=$(func_pipeline_parse_value "$idx" dev) snd=$(func_pipeline_parse_value "$idx" snd) - # expect is tcl language script - # expr rand(): produces random numbers between 0 and 1 - # after ms: Ms must be an integer giving a time in milliseconds. - # The command sleeps for ms milliseconds and then returns. - dlogi "Entering expect script with: - $cmd $SOF_ALSA_OPTS $cmd_opts -D $dev -r $rate -c $channel -f $fmt -vv -i $file_name -q" - - expect < $repeat_count } { exit 0 } - exp_continue - } -} -exit 1 -END - ret=$? + ret=0 + (set -x + # The 4 expect arguments first, then $cmd + $cmd arguments + # shellcheck disable=SC2086 + "$TOPDIR"/case-lib/apause.exp "$cmd" "$repeat_count" "$rnd_min" "$rnd_range" \ + "$cmd" $SOF_ALSA_OPTS $cmd_opts -D "$dev" -r "$rate" -c "$channel" -f "$fmt" \ + -vv -i "$file_name" + ) || ret=$? + #flush the output echo if [ $ret -ne 0 ]; then + echo "apause.exp returned: $ret" func_lib_lsof_error_dump "$snd" sof-process-kill.sh || dlogw "Kill process catch error"