From 2e0ebd42be233d03c183cabf4cf9092895409f94 Mon Sep 17 00:00:00 2001 From: Marc Herbert Date: Wed, 31 Jul 2024 20:01:31 -0700 Subject: [PATCH 1/3] apause.exp: search/replace "recording" with "active" The script was originally tested with arecord but it works with aplay exactly the same. Stop saying "recording" when playing, it's confusing. Signed-off-by: Marc Herbert --- case-lib/apause.exp | 20 ++++++++++---------- 1 file changed, 10 insertions(+), 10 deletions(-) diff --git a/case-lib/apause.exp b/case-lib/apause.exp index 66fdec3d..daecbed6 100755 --- a/case-lib/apause.exp +++ b/case-lib/apause.exp @@ -111,8 +111,8 @@ 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 +# states: active, pause_requested, paused, active_requested +set state active_requested set in_max_burst false set volume_always_zero true @@ -182,13 +182,13 @@ expect { switch $state { - recording { - log 2 "Recording volume #... | xx%:\n[cr_to_lf $expect_out(buffer)]" + active { + log 2 "Volume #... | __%:\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)]" + log 2 "Volume #... | __% left after requesting pause:\n[cr_to_lf $expect_out(buffer)]" exp_continue } @@ -198,12 +198,12 @@ expect { exit 1 } - recording_requested { - # First volume line printed since unpaused; recording successfully started! - set state recording + active_requested { + # First volume line printed since unpaused; stream successfully started! + set state active set _record_for [rand_min_range $rnd_min $rnd_range] - log 1 "($pauses_counter/$repeat_count) Found volume ### | xx%, recording for $_record_for ms" + log 1 "($pauses_counter/$repeat_count) Found volume ### | __%, active for $_record_for ms" set _delay [substract_time_since_last_space $_record_for] after $_delay "press_space; set state pause_requested" @@ -241,7 +241,7 @@ expect { 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" + after $_delay "press_space; set state active_requested" log 3 "last_space_time=$last_space_time; timer in $_delay" From e5f9248c07e8c1b78a8791a9eb2e14bf12a3475d Mon Sep 17 00:00:00 2001 From: Marc Herbert Date: Wed, 31 Jul 2024 20:18:30 -0700 Subject: [PATCH 2/3] apause.exp: catch and print error messages and exit immediately Fail fast and avoid timeouts. This is especially important considering pause will soon be disabled by default: - https://github.com/thesofproject/linux/pull/5041 Signed-off-by: Marc Herbert --- case-lib/apause.exp | 12 ++++++++++++ 1 file changed, 12 insertions(+) diff --git a/case-lib/apause.exp b/case-lib/apause.exp index daecbed6..36151732 100755 --- a/case-lib/apause.exp +++ b/case-lib/apause.exp @@ -137,8 +137,20 @@ set volume_always_zero true expect { + # `man re_syntax` claims that Tcl regular expressions are compliant + # with the basic and extended POSIX ones while adding a 3rd, + # extended flavor. It's not clear which flavor `expect -re` uses + # but it's not the basic one. + # Use {} not "" to avoid quoting issues and backslash proliferation. + # When multiple patterns match, first pattern wins. + -nocase -re {error.*\r|PAUSE.*no[[:blank:]]*hw[[:blank:]]*support.*\r} { + set buffer_with_lf "[cr_to_lf $expect_out(buffer)]" + log 0 "ERROR: $buffer_with_lf" + exit 1 + } + # Volume xx% or MAX line # # When not backpressured by a sleeping (=bad!) Expect process, From d25ac5babd852db9e4bb8476acdb906a881697b3 Mon Sep 17 00:00:00 2001 From: Marc Herbert Date: Wed, 31 Jul 2024 20:20:01 -0700 Subject: [PATCH 3/3] apause.exp: promote unexpected "PAUSE" feedback from warning to failure Experience with https://github.com/thesofproject/linux/issues/5109 shows that this warning never seems harmless: the test ends up timing out and failing anyway. So, better failing fast for clearer and better logs. Also increase the log level of press_space() to avoid state confusion. Signed-off-by: Marc Herbert --- case-lib/apause.exp | 10 +++------- 1 file changed, 3 insertions(+), 7 deletions(-) diff --git a/case-lib/apause.exp b/case-lib/apause.exp index 36151732..e9abaaf7 100755 --- a/case-lib/apause.exp +++ b/case-lib/apause.exp @@ -81,7 +81,7 @@ proc rel_time_ms {} { proc press_space {} { global last_space_time - log 2 "Pressing SPACE" + log 1 "Pressing SPACE" send " " set last_space_time [rel_time_ms] log 3 "last_space_time set to $last_space_time" @@ -237,12 +237,8 @@ expect { {=== PAUSE ===} { if {$state != "pause_requested"} { - # TODO: upgrade this to an ERROR if we want to fix pause bugs like - # https://github.com/thesofproject/linux/issues/5109 - # As of July 2024, pause is rather being disabled: - # https://github.com/thesofproject/linux/pull/5041 - log 0 "WARNING: received == PAUSE == while in state $state! Ignoring." - exp_continue + log 0 "ERROR: received == PAUSE == while in state $state!" + exit 1 } set state paused