Skip to content

Commit

Permalink
Add new Expect script tools/apause.exp
Browse files Browse the repository at this point in the history 
This all started as an effort to solve test failures caused by "MAX"
volume. See thesofproject#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 <[email protected]>
  • Loading branch information
@marc-hb
marc-hb committed Jul 10, 2024
1 parent c0bd6d4 commit 538e8f7
Showing 1 changed file with 268 additions and 0 deletions.
268 changes: 268 additions & 0 deletions case-lib/apause.exp
View file
Original file line number Diff line number Diff line change
@@ -0,0 +1,268 @@
#!/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 ===} {
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"

0 comments on commit 538e8f7

Please sign in to comment.