Skip to content

Commit 006946c

Browse files
marc-hbmarc-hb
committed
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 <marc.herbert@intel.com>
1 parent 7fd8c29 commit 006946c

1 file changed

Lines changed: 274 additions & 0 deletions

File tree

‎case-lib/apause.exp‎

Lines changed: 274 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,274 @@
1+
#!/usr/bin/env expect
2+
3+
# If you're new to expect:
4+
#
5+
# - Expect is "only" a Tcl extension and Tcl command.
6+
# An "expect script" is a somewhat misleading shorthand for "a Tcl
7+
# script that happens to use expect/"
8+
#
9+
# - So, you can't understand this script (or any expect script) without
10+
# some minimum Tcl knowledge. Especially: strings, quoting, lists and
11+
# delayed evaluations.
12+
#
13+
# - Expect resources on the Internet are hit-and-miss. Don Libes' book
14+
# "Exploring Expect" is great: buy the book or check whether your
15+
# employer has an online subscription. That book has a really nice and
16+
# short (single chapter) Tcl introduction too.
17+
# Tcl resources on the Internet are much better and expect resources.
18+
#
19+
# - The man pages are not good for learning but they are a very useful
20+
# references: run `apt install tcl8*-doc` or equivalent to get Tcl man
21+
# pages, then: `man [3tcl] expect`, `man [3tcl] after`, etc.
22+
#
23+
# - Use the interactive `rlwrap tclsh` to experiment.
24+
#
25+
26+
# log level: 0 = initialization, warnings and errors only, 1 = normal, 2+ = debug
27+
set log_level 1
28+
29+
# Set to 1 only when you're desperate: this randomly interleaves
30+
# aplay's output with output from this script.
31+
log_user 0
32+
33+
# aplay -vv is chatty: no need to wait for very long
34+
set timeout 5
35+
36+
proc log {lvl msg} {
37+
global log_level cmd_shortname
38+
if {$lvl <= $log_level} {
39+
puts "t=[rel_time_ms] ms: $cmd_shortname: $msg"
40+
}
41+
}
42+
43+
# Pop the first element of the list argument.
44+
# Equivalent to "shift" in shell.
45+
proc lshift {args} {
46+
# "upvar" required to escape scope and change argument in place
47+
upvar $args args_up
48+
set first [lindex $args_up 0]
49+
set args_up [lreplace $args_up 0 0]
50+
return $first
51+
}
52+
53+
# Random numbers between min and min+range
54+
proc rand_min_range {min range} {
55+
return [expr $min + int([expr rand() * $range])]
56+
}
57+
58+
set cmd_shortname [lshift argv]
59+
set repeat_count [lshift argv]
60+
set rnd_min [lshift argv]
61+
set rnd_range [lshift argv]
62+
63+
# Should really be 200 ms because of the round-trip between pressing
64+
# "space" and aplay's acknowledgement + other various delays everywhere.
65+
# Keep it that small for now for backwards compatibility.
66+
if {$rnd_min < 20} {
67+
puts "$argv0 ERROR: rnd_min=$rnd_min argument is lower than 100ms"
68+
exit 1
69+
}
70+
71+
# How many times we paused
72+
set pauses_counter 0
73+
74+
# Logging needs this early. Will reset better later.
75+
set start_time_ms [clock milliseconds]
76+
77+
proc rel_time_ms {} {
78+
global start_time_ms
79+
return [expr [clock milliseconds] - $start_time_ms]
80+
}
81+
82+
proc press_space {} {
83+
global last_space_time
84+
log 2 "Pressing SPACE"
85+
send " "
86+
set last_space_time [rel_time_ms]
87+
log 3 "last_space_time set to $last_space_time"
88+
}
89+
90+
proc substract_time_since_last_space {duration} {
91+
global last_space_time
92+
set _delay [expr $duration - ([rel_time_ms] - $last_space_time)]
93+
# Don't return negative values if we already passed the deadline.
94+
# Don't return zero either to avoid interrupting ourselves (just in
95+
# case Tcl thought it would be a good idea)
96+
return [tcl::mathfunc::max 1 $_delay]
97+
}
98+
99+
# aplay's VU-meter uses CRs to write over itself and avoid terminal scrolling.
100+
# But when debugging we want to see everything.
101+
proc cr_to_lf {arg} {
102+
set _lf [regsub "\r" $arg "\n"]
103+
return [string trim $_lf]
104+
}
105+
106+
# Use all remaining arguments as the command to invoke. Example:
107+
#
108+
# arecord $cmd_opts -D $dev -r $rate -c $channel -f $fmt -vv -i $file_name ...
109+
log 0 "$argv0 spawning: $argv"
110+
spawn {*}$argv
111+
set start_time_ms [clock milliseconds]; # re-adjust
112+
set last_space_time 0 ; # could not resist that name
113+
114+
# states: recording, pause_requested, paused, recording_requested
115+
set state recording_requested
116+
117+
set in_max_burst false
118+
set volume_always_zero true
119+
120+
# Key `expect` matching facts to keep in mind:
121+
#
122+
# 1. `expect` never cares about newlines on its own. You must use `\r`
123+
# and/or `\n` _everywhere_ you care about newlines.
124+
#
125+
# 2. When to use \r versus \n versus \r\n (CRLF) in expect unfortunately
126+
# requires some tty _and_ arecord VU-meter knowledge and is a bit too
127+
# complicated to be summarized here.
128+
#
129+
# 3. When nothing matches, expect keeps reading and keeps looking
130+
# forward. As soon as something matches, `expect` _ignores_ what did
131+
# not match earlier. Except when using ^ which is the "start of
132+
# input" anchor (NOT a "start of line" anchor)
133+
#
134+
# 4. Conversely, whatever is left AFTER a match will always be submitted
135+
# for matching again: exactly like it has not arrived yet (otherwise it
136+
# would be always racy).
137+
138+
expect {
139+
140+
# When multiple patterns match, first pattern wins.
141+
142+
# Volume xx% or MAX line
143+
#
144+
# When not backpressured by a sleeping (=bad!) expect,
145+
# aplay seems to update its VU-meter about once every 100ms.
146+
-re {#[^\r\n]*\| (..*%|MAX)\r} {
147+
148+
# - $expect_out(0,string) = match
149+
# - $expect_out(buffer) = everything before match + match
150+
151+
set buffer_with_lf "[cr_to_lf $expect_out(buffer)]"
152+
153+
# Always print the audio stream configuration preamble
154+
if [regexp {PCM card} "$buffer_with_lf"] {
155+
log 0 "$buffer_with_lf"
156+
}
157+
158+
if [regexp {\| MAX} "$buffer_with_lf"] {
159+
if { ! $in_max_burst } {
160+
# TODO: upgrade this to a failure once all ALSA settings have been fixed.
161+
log 0 "WARNING: volume MAX! Bug or bad ALSA settings?"
162+
log 0 "$buffer_with_lf"
163+
set in_max_burst true
164+
}
165+
} else {
166+
set in_max_burst false
167+
}
168+
169+
if $volume_always_zero {
170+
# This is not perfect because if `expect` becomes very slow
171+
# for some unknown reason, then there could be _multiple_
172+
# volume lines in a single of these buffer iterations and then we
173+
# could miss some non-zeros.
174+
# This is very unlikely though so this is statically good enough.
175+
if {! [regexp {\| ( |0)0%} "$buffer_with_lf"]} {
176+
set volume_always_zero false
177+
}
178+
}
179+
180+
switch $state {
181+
182+
recording {
183+
log 2 "Recording volume #... | xx%:\n[cr_to_lf $expect_out(buffer)]"
184+
exp_continue
185+
}
186+
187+
pause_requested {
188+
log 2 "Volume #... | xx% left after requesting pause:\n[cr_to_lf $expect_out(buffer)]"
189+
exp_continue
190+
}
191+
192+
paused {
193+
log 0 "ERROR: found VOLUME while paused!"
194+
log 0 "$buffer_with_lf"
195+
exit 1
196+
}
197+
198+
recording_requested {
199+
# First volume line printed since unpaused; recording successfully started!
200+
set state recording
201+
202+
set _record_for [rand_min_range $rnd_min $rnd_range]
203+
log 1 "($pauses_counter/$repeat_count) Found volume ### | xx%, recording for $_record_for ms"
204+
205+
set _delay [substract_time_since_last_space $_record_for]
206+
after $_delay "press_space; set state pause_requested"
207+
log 3 "last_space_time=$last_space_time; timer in $_delay"
208+
209+
# Debug matched string
210+
log 2 "$buffer_with_lf"
211+
exp_continue
212+
}
213+
214+
default {
215+
log 0 "ERROR: unexpected state=$state! Volume is:\n[cr_to_lf $expect_out(buffer)]"
216+
exit 1
217+
}
218+
219+
}
220+
221+
}
222+
223+
{=== PAUSE ===} {
224+
if {$state != "pause_requested"} {
225+
# TODO: upgrade this to an ERROR?
226+
log 0 "WARNING: received == PAUSE == while in state $state! Ignoring."
227+
exp_continue
228+
}
229+
230+
set state paused
231+
# Re-enable the MAX warning
232+
set in_max_burst false
233+
234+
set _pausing_for [rand_min_range $rnd_min $rnd_range]
235+
log 1 "($pauses_counter/$repeat_count) Found === PAUSE === , pausing for $_pausing_for ms"
236+
237+
set _delay [substract_time_since_last_space $_pausing_for]
238+
after $_delay "press_space; set state recording_requested"
239+
log 3 "last_space_time=$last_space_time; timer in $_delay"
240+
241+
242+
incr pauses_counter
243+
if { $pauses_counter <= $repeat_count } {
244+
exp_continue
245+
}
246+
# Normal exit of the "expect" command here
247+
}
248+
249+
# This overlaps with the main volume case above but it's very useful logging when
250+
# forgetting to pass a double -vv and timing out
251+
-re {PCM card[^#]*} {
252+
log 0 "Preamble:\n$expect_out(buffer)"
253+
exp_continue
254+
}
255+
256+
timeout {
257+
log 0 "ERROR: $argv0 timed out. Did you use -vv?"
258+
exit 1
259+
}
260+
261+
eof {
262+
log 0 "ERROR: $argv0: EOF."
263+
log 0 "$expect_out(buffer)"
264+
exit 1
265+
}
266+
}
267+
268+
if $volume_always_zero {
269+
log 0 "WARNING: volume was always 00%!"
270+
}
271+
272+
# TODO: collect exit status with explicit exp_close + exp_wait?
273+
274+
log 0 "SUCCESS: $argv0 $argv"

0 commit comments

Comments
 (0)