check-pause-resume: handle volume MAX output in expect #931

fredoh9 · 2022-07-13T00:03:45Z

When volume is MAX, current expect misses the case. Why volume is MAX is
separate question. Momentary pop can be ingored but if volume is 100% DC
return error.
And added for ignoring dump-hw-params and last case is anything else,
it means unexpected outputs, will return error also.

This is example of output from aplay or arecord.

Playing
"## + | 11%"
When paused
"=== PAUSE ==="
When volume is MAX
"##################################################+| MAX"

Signed-off-by: Fred Oh [email protected]

[BUG] arecord TGLU_SKU0A32_SDCA ########+| MAX linux#3766

test-case/check-pause-resume.sh

fredoh9 · 2022-07-13T00:17:11Z

multiple-pause-resume.sh need to be handled in same way. I will update the same shortly

marc-hb

MAX case is same as playing case.

It it is the same then please don't copy/paste the code, it must be possible to match both and share the code.

Also, please add a fallback case that prints an error so no one wastes hours next time aplay prints something unexpected.

But more importantly: this test never failed like this. Why is MAX suddenly OK? This looks like a firmware bug?!

EDIT: because alsa settings were accidentally changed: thesofproject/linux#3766

multiple-pause-resume.sh need to be handled in same way. I will update the same shortly

Maybe it's time to move some new .expect file shared between tests?

fredoh9 · 2022-07-13T00:44:16Z

@marc-hb I will check how we can share the same code in expect. Need to search expect manual

fredoh9 · 2022-07-13T17:13:56Z

@marc-hb still looking for sharing the case in expect script.

And also I'm trying to handle 'else' case but expect script didn't work like that, i thought it will match top to bottom but "*" case hit all the time.

diff --git a/test-case/check-pause-resume.sh b/test-case/check-pause-resume.sh
index 170aff7..cdcd203 100755
--- a/test-case/check-pause-resume.sh
+++ b/test-case/check-pause-resume.sh
@@ -116,6 +116,18 @@ expect {
         if { \$i > $repeat_count } { exit 0 }
         exp_continue
     }
+    "*#*+*MAX" {
+        set sleep_t [expr int([expr rand() * $rnd_range]) + $rnd_min ]
+        puts "\r(\$i/$repeat_count) Wait for \$sleep_t ms before pause"
+        send " "
+        after \$sleep_t
+        exp_continue
+    }
+    "*" {
+        puts "\r Invalid output detected, Wait for 500ms and recheck"
+        set sleep_t 500
+        after \$sleep_t
+        exp_continue
+    }
 }
 exit 1
 END

greg-intel · 2022-07-13T18:06:12Z

test-case/multiple-pause-resume.sh

@@ -135,6 +135,13 @@ expect {
        if { \$i > $repeat_count } { exit 0 }
        exp_continue
    }
+    "*#*+*MAX" {
+        set sleep_t [expr int([expr rand() * $rnd_range]) + $rnd_min ]


Do our tests generally have a lot of randomness? Doesn't that make failures less deterministic?

In general we don't like randomness in testing. In this pause/resume, we intentionally introduce randomness on ranger of interval to discover easily fw bug

fredoh9 · 2022-07-13T18:21:02Z

I missed check-pause-release-suspend-resume.sh has expect block as well.

marc-hb · 2022-07-13T18:37:17Z

And also I'm trying to handle 'else' case but expect script didn't work like that, i thought it will match top to bottom but "*" case hit all the time.

Strange. From https://www.tcl.tk/man/expect5.31/expect.1.html

In the event that multiple patterns match, the one appearing first is used to select a body.

EDIT: this is probably because of a lack of \n in the expect script.

fredoh9 · 2022-07-13T18:57:50Z

This is the source code for VU meter output. Last line output will be "!clip"? I think this is only error we can handle extra.

https://github.com/thesofproject/alsa-utils/blob/a566f8a0ed6d7ca5fd6ae2d224f3f28654a2f3be/aplay/aplay.c#L1760

static void print_vu_meter_mono(int perc, int maxperc)
{
	const int bar_length = 50;
	char line[80];
	int val;

	for (val = 0; val <= perc * bar_length / 100 && val < bar_length; val++)
		line[val] = '#';
	for (; val <= maxperc * bar_length / 100 && val < bar_length; val++)
		line[val] = ' ';
	line[val] = '+';
	for (++val; val <= bar_length; val++)
		line[val] = ' ';
	if (maxperc > 99)
		sprintf(line + val, "| MAX");
	else
		sprintf(line + val, "| %02i%%", maxperc);
	fputs(line, stderr);
	if (perc > 100)
		fprintf(stderr, _(" !clip  "));
}

This is "PAUSE" output
https://github.com/thesofproject/alsa-utils/blob/a566f8a0ed6d7ca5fd6ae2d224f3f28654a2f3be/aplay/aplay.c#L1622

static void check_stdin(void)
{
	unsigned char b;

	if (!interactive)
		return;
	if (fd != fileno(stdin)) {
		while (read(fileno(stdin), &b, 1) == 1) {
			if (b == ' ' || b == '\r') {
				while (read(fileno(stdin), &b, 1) == 1);
				fprintf(stderr, _("\r=== PAUSE ===                                                            "));
				fflush(stderr);
				do_pause();
				fprintf(stderr, "                                                                          \r");
				fflush(stderr);
			}
		}
	}
}

fredoh9 · 2022-07-13T22:14:15Z

I missed check-pause-release-suspend-resume.sh has expect block as well.

check-pause-release-suspend-resume.sh is not being used by SOF CI yet. I can add FIXME note for it

fredoh9 · 2022-07-14T00:09:17Z

I tested locally and pushed my changes, I should whether check device test is going smooth.

thank you for your review.
@marc-hb @greg-intel @keqiaozhang @aiChaoSONG @miRoox @XiaoyunWu6666

test-case/check-pause-release-suspend-resume.sh

test-case/multiple-pause-resume.sh

marc-hb · 2022-07-14T00:36:33Z

Please submit the error handling commit in a different PR so we can fast track it.

fredoh9 · 2022-07-14T14:50:31Z

From device test, multiple-pause-resume.sh failed in multiple platforms. It is due to
Error: unexpected output detected, exit 1

2022-07-14 00:17:42 UTC [REMOTE_INFO] pipeline: Jack Out DeepBuffer with aplay
2022-07-14 00:17:42 UTC [REMOTE_INFO] pipeline: HDMI 2 with aplay
2022-07-14 00:17:42 UTC [REMOTE_INFO] Check expect exit status
2022-07-14 00:17:42 UTC [REMOTE_INFO] Jack Out DeepBuffer to command: aplay -D hw:0,31 -r 48000 -c 2 -f S16_LE -vv -i /dev/zero -q
spawn aplay -D hw:0,31 -r 48000 -c 2 -f S16_LE -vv -i /dev/zero -q
2022-07-14 00:17:42 UTC [REMOTE_INFO] HDMI 3 to command: aplay -D hw:0,7 -r 48000 -c 2 -f S16_LE -vv -i /dev/zero -q
2022-07-14 00:17:42 UTC [REMOTE_INFO] wait for expect process finished
spawn aplay -D hw:0,7 -r 48000 -c 2 -f S16_LE -vv -i /dev/zero -q
Hardware PCM card 0 'sof-soundwire' device 31 subdevice 0
Its setup is:
Error: unexpected output detected, exit 1

I'm able to reproduce same error with TGLU_SKU0A32_SDCA also. It looks some more messages are left to be handled.

plbossart · 2022-07-14T14:57:14Z

@fredoh9 I am struggling to figure out what volume has to do with pause_push/pause_release. I went through the entire thread and I have zero understanding of the issue.

fredoh9 · 2022-07-14T15:04:27Z

@plbossart First problem is expect script which trigger spacebar event to aplay/arecord in interactive mode. "MAX" volume was not handled properly. Momentary MAX can be ignored but hw:0.4 is 100% DC only, this case fails 100%.

2nd problem, why is hw:0,4 input becoming DC, @marc-hb track the daily test, he think kernel regression.

plbossart · 2022-07-14T15:40:17Z

What is the relationship between pressing the space bar and volume control @fredoh9 ?

fredoh9 · 2022-07-14T15:53:02Z

What is the relationship between pressing the space bar and volume control @fredoh9 ?

Right, nothing to do with. But expect script to look for aplay/arecord output to decide what to do. When first wrote the test script, we didn't expect MAX volume is one of possibility. That's why I said first problem is on expect script.

marc-hb · 2022-07-25T15:55:29Z

@plbossart OK?

plbossart · 2022-07-25T17:03:54Z

@plbossart OK?

We confirmed with Realtek that the audio settings are incorrect, so I am not sure why any changes are needed in sof-test. I would fix the audio settings first instead of making the tool work-around the bad settings.

Edit: link to thread with Realtek thesofproject/linux#3766 (comment)

marc-hb · 2022-07-25T23:44:27Z

@fredoh9 can you confirm the test WILL STILL FAIL with this PR in the same system configuration as before?

I don't understand what this PR fixes, nor that the patch does.

marc-hb · 2024-06-18T02:02:59Z

SOFCI TEST

marc-hb · 2024-06-18T16:32:20Z

https://sof-ci.01.org/softestpr/PR931/build519/devicetest/index.html?model=MTLP_RVP_HDA&testcase=multiple-pause-resume-50 shows some "MAX" traces but now looking different. Saving the link for future investigation.

fredoh9 · 2024-06-18T19:11:35Z

The real problem is that the DMIC volume suddenly becomes 100% for no reason. I suspect something to do with electrical problem with DMIC transducer board, but don't know the root cause. Test failure rate varies between device/DMIC board.

The whole point of this PR is to match the expected output regardless of the DMIC output or volume level.

@marc-hb I'm looking at this PR now. Even with this PR, it silll fails when DMIC MAX volume happens. Looks the matching is broken. I will update the fix shortly.

fredoh9 · 2024-06-18T19:18:51Z

I scrolled up to read all the discussion, we concluded the volume MAX is failure case, not much thing to do with this PR.
Instead I will check the DMIC connections and replace with different DMIC board.

marc-hb · 2024-06-18T20:22:19Z

I scrolled up to read all the discussion, we concluded the volume MAX is failure case, not much thing to do with this PR.

This PR is all about handling that failure better.

marc-hb

I tested this script with expect -d and it works "by accident" either before or after the PR.
cc:

soundwire: intel_auxdevice: add kernel parameter for mclk divider linux#5067 (comment)

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 <[email protected]>

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]>

marc-hb · 2024-07-10T16:26:01Z

I realized the existing (and duplicated) expect script was hopelessly broken so I rewrote it and submitted it in:

Add new Expect script tools/apause.exp #1218

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]>

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 <[email protected]>

marc-hb · 2024-07-15T22:29:47Z

Alternative Add new Expect script tools/apause.exp #1218 was merged so I think there are only some comments that are still valid in this PR.
While testing Add new Expect script tools/apause.exp #1218, I found that the "MAX" pop was still present on TGLU_SKU0A32 so I just re-opened this:
[BUG] arecord TGLU_SKU0A32_SDCA ########+| MAX linux#3766

Comments rescued from superseded thesofproject#931. Signed-off-by: Fred Oh <[email protected]>

marc-hb · 2024-07-19T01:47:28Z

test-case/check-pause-resume.sh

@@ -96,18 +96,21 @@ do
    dlogi "Entering expect script with:
      $cmd $SOF_ALSA_OPTS $cmd_opts -D $dev -r $rate -c $channel -f $fmt -vv -i $file_name -q"

+    # NOTE: Purposely we don't handle 'Volume MAX' case. So that the MAX output can fall into
+    #       'anything else' case and error out.
+    # FIXME: share this expect script as a common function


@fredoh9 I re-submitted these comments in new #1222. I think all the rest has been superseded by merged #1218. OK to abandon this?

fredoh9 · 2024-07-19T22:35:14Z

Marc added better solution.

Comments rescued from superseded #931. Signed-off-by: Fred Oh <[email protected]>

fredoh9 requested a review from a team as a code owner July 13, 2022 00:03

fredoh9 commented Jul 13, 2022

View reviewed changes

test-case/check-pause-resume.sh Outdated Show resolved Hide resolved

fredoh9 commented Jul 13, 2022

View reviewed changes

test-case/check-pause-resume.sh Outdated Show resolved Hide resolved

marc-hb requested changes Jul 13, 2022

View reviewed changes

fredoh9 force-pushed the fix/pause-resume-expect branch from e2e2620 to d84272f Compare July 13, 2022 00:40

greg-intel reviewed Jul 13, 2022

View reviewed changes

fredoh9 force-pushed the fix/pause-resume-expect branch from d84272f to 244c198 Compare July 14, 2022 00:03

fredoh9 requested review from XiaoyunWu6666, aiChaoSONG, keqiaozhang, miRoox, greg-intel and marc-hb July 14, 2022 00:07

marc-hb requested changes Jul 14, 2022

View reviewed changes

test-case/check-pause-release-suspend-resume.sh Outdated Show resolved Hide resolved

test-case/multiple-pause-resume.sh Outdated Show resolved Hide resolved

fredoh9 force-pushed the fix/pause-resume-expect branch from 244c198 to ab6d555 Compare July 14, 2022 15:49

fredoh9 force-pushed the fix/pause-resume-expect branch from ab6d555 to b8cb4bb Compare July 14, 2022 16:27

marc-hb added the area:Ansible Problems that Ansible can help with label Jul 25, 2022

marc-hb mentioned this pull request Nov 28, 2022

[BUG] IPC4 volume windows ramp was broken with latest sof-dev kernel and sof firmware thesofproject/linux#4026

Closed

marc-hb mentioned this pull request Dec 19, 2022

sof-logger: exit with error if malloc fails thesofproject/sof#6847

Merged

marc-hb mentioned this pull request Mar 13, 2023

Volume reset for alsabat testing #1010

Merged

marc-hb mentioned this pull request Jun 27, 2023

volume-basic-test.sh: don't skip "playback volume" controls #1068

Closed

marc-hb mentioned this pull request Jun 7, 2024

LNL HDA pause-release MAX issue thesofproject/linux#5048

Closed

marc-hb requested changes Jun 19, 2024

View reviewed changes

marc-hb mentioned this pull request Jul 9, 2024

Add new Expect script tools/apause.exp #1218

Merged

marc-hb pushed a commit to marc-hb/sof-test that referenced this pull request Jul 18, 2024

check-pause-release-suspend-resume.sh: add two FIXMEs

5d983e6

Comments rescued from superseded thesofproject#931. Signed-off-by: Fred Oh <[email protected]>

marc-hb mentioned this pull request Jul 19, 2024

case-lib/apause.exp: fix error message and comments #1222

Merged

marc-hb reviewed Jul 19, 2024

View reviewed changes

fredoh9 closed this Jul 19, 2024

marc-hb pushed a commit that referenced this pull request Jul 20, 2024

check-pause-release-suspend-resume.sh: add two FIXMEs

edd7fa9

Comments rescued from superseded #931. Signed-off-by: Fred Oh <[email protected]>

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

check-pause-resume: handle volume MAX output in expect #931

check-pause-resume: handle volume MAX output in expect #931

fredoh9 commented Jul 13, 2022 •

edited by marc-hb

Loading

fredoh9 commented Jul 13, 2022

marc-hb left a comment •

edited

Loading

fredoh9 commented Jul 13, 2022

fredoh9 commented Jul 13, 2022 •

edited

Loading

greg-intel Jul 13, 2022

fredoh9 Jul 13, 2022

fredoh9 commented Jul 13, 2022

marc-hb commented Jul 13, 2022 •

edited

Loading

fredoh9 commented Jul 13, 2022 •

edited

Loading

fredoh9 commented Jul 13, 2022

fredoh9 commented Jul 14, 2022

marc-hb commented Jul 14, 2022

fredoh9 commented Jul 14, 2022

plbossart commented Jul 14, 2022

fredoh9 commented Jul 14, 2022 •

edited

Loading

plbossart commented Jul 14, 2022

fredoh9 commented Jul 14, 2022

marc-hb commented Jul 25, 2022

plbossart commented Jul 25, 2022 •

edited

Loading

marc-hb commented Jul 25, 2022

marc-hb commented Jun 18, 2024

marc-hb commented Jun 18, 2024

fredoh9 commented Jun 18, 2024

fredoh9 commented Jun 18, 2024

marc-hb commented Jun 18, 2024 •

edited

Loading

marc-hb left a comment •

edited

Loading

marc-hb commented Jul 10, 2024

marc-hb commented Jul 15, 2024

marc-hb Jul 19, 2024

fredoh9 commented Jul 19, 2024

check-pause-resume: handle volume MAX output in expect #931

check-pause-resume: handle volume MAX output in expect #931

Conversation

fredoh9 commented Jul 13, 2022 • edited by marc-hb Loading

fredoh9 commented Jul 13, 2022

marc-hb left a comment • edited Loading

Choose a reason for hiding this comment

fredoh9 commented Jul 13, 2022

fredoh9 commented Jul 13, 2022 • edited Loading

greg-intel Jul 13, 2022

Choose a reason for hiding this comment

fredoh9 Jul 13, 2022

Choose a reason for hiding this comment

fredoh9 commented Jul 13, 2022

marc-hb commented Jul 13, 2022 • edited Loading

fredoh9 commented Jul 13, 2022 • edited Loading

fredoh9 commented Jul 13, 2022

fredoh9 commented Jul 14, 2022

marc-hb commented Jul 14, 2022

fredoh9 commented Jul 14, 2022

plbossart commented Jul 14, 2022

fredoh9 commented Jul 14, 2022 • edited Loading

plbossart commented Jul 14, 2022

fredoh9 commented Jul 14, 2022

marc-hb commented Jul 25, 2022

plbossart commented Jul 25, 2022 • edited Loading

marc-hb commented Jul 25, 2022

marc-hb commented Jun 18, 2024

marc-hb commented Jun 18, 2024

fredoh9 commented Jun 18, 2024

fredoh9 commented Jun 18, 2024

marc-hb commented Jun 18, 2024 • edited Loading

marc-hb left a comment • edited Loading

Choose a reason for hiding this comment

marc-hb commented Jul 10, 2024

marc-hb commented Jul 15, 2024

marc-hb Jul 19, 2024

Choose a reason for hiding this comment

fredoh9 commented Jul 19, 2024

fredoh9 commented Jul 13, 2022 •

edited by marc-hb

Loading

marc-hb left a comment •

edited

Loading

fredoh9 commented Jul 13, 2022 •

edited

Loading

marc-hb commented Jul 13, 2022 •

edited

Loading

fredoh9 commented Jul 13, 2022 •

edited

Loading

fredoh9 commented Jul 14, 2022 •

edited

Loading

plbossart commented Jul 25, 2022 •

edited

Loading

marc-hb commented Jun 18, 2024 •

edited

Loading

marc-hb left a comment •

edited

Loading