Closed Bug 1765312 Opened 2 years ago Closed 2 years ago

Intermittent TestAudioInputSource.ErrorCallback |

Categories

(Testing :: GTest, defect, P5)

defect

Tracking

(firefox-esr91 unaffected, firefox99 unaffected, firefox100 unaffected, firefox101 fixed)

RESOLVED FIXED
101 Branch
Tracking Status
firefox-esr91 --- unaffected
firefox99 --- unaffected
firefox100 --- unaffected
firefox101 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: chunmin)

References

(Regression)

Details

(Keywords: intermittent-failure, regression, Whiteboard: [retriggered])

Attachments

(1 file)

Filed by: csabou [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=374956034&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/FLoAjdZCR5GtDTpT7WHk_Q/runs/0/artifacts/public/logs/live_backing.log


[task 2022-04-19T10:51:17.746Z] 10:51:17     INFO -  TEST-PASS | TestAudioInputSource.DataOutputBeforeStartAndAfterStop | test completed (time: 29ms)
[task 2022-04-19T10:51:17.748Z] 10:51:17     INFO -  TEST-START | TestAudioInputSource.ErrorCallback
[task 2022-04-19T10:51:17.792Z] 10:51:17  WARNING -  TEST-UNEXPECTED-FAIL | TestAudioInputSource.ErrorCallback |
[task 2022-04-19T10:51:17.793Z] 10:51:17     INFO -  Unexpected mock function call - returning directly.
[task 2022-04-19T10:51:17.793Z] 10:51:17     INFO -      Function call: AudioStateCallback(1, 4-byte object <01-00 00-00>)
[task 2022-04-19T10:51:17.793Z] 10:51:17     INFO -  Google Mock tried the following 2 expectations, but none matched:
[task 2022-04-19T10:51:17.794Z] 10:51:17     INFO -  /builds/worker/checkouts/gecko/dom/media/gtest/TestAudioInputSource.cpp(197): tried expectation #0: EXPECT_CALL(*listener, AudioStateCallback( sourceId, AudioInputSource::EventListener::State::Started))...
[task 2022-04-19T10:51:17.795Z] 10:51:17     INFO -    Expected arg #1: is equal to 4-byte object <00-00 00-00>
[task 2022-04-19T10:51:17.795Z] 10:51:17     INFO -             Actual: 4-byte object <01-00 00-00>
[task 2022-04-19T10:51:17.795Z] 10:51:17     INFO -           Expected: to be called once
[task 2022-04-19T10:51:17.795Z] 10:51:17     INFO -             Actual: called once - saturated and active
[task 2022-04-19T10:51:17.796Z] 10:51:17     INFO -  /builds/worker/checkouts/gecko/dom/media/gtest/TestAudioInputSource.cpp(200): tried expectation #1: EXPECT_CALL(*listener, AudioStateCallback( sourceId, AudioInputSource::EventListener::State::Error))...
[task 2022-04-19T10:51:17.797Z] 10:51:17     INFO -    Expected arg #1: is equal to 4-byte object <03-00 00-00>
[task 2022-04-19T10:51:17.797Z] 10:51:17     INFO -             Actual: 4-byte object <01-00 00-00>
[task 2022-04-19T10:51:17.797Z] 10:51:17     INFO -           Expected: to be called once
[task 2022-04-19T10:51:17.797Z] 10:51:17     INFO -             Actual: called once - saturated and active @ (null):-1
[task 2022-04-19T10:51:17.797Z] 10:51:17  WARNING -  TEST-UNEXPECTED-FAIL | TestAudioInputSource.ErrorCallback | test completed (time: 47ms)
[task 2022-04-19T10:51:17.798Z] 10:51:17     INFO -  TEST-START | TestAudioInputSource.DeviceChangedCallback
[task 2022-04-19T10:51:17.826Z] 10:51:17     INFO -  TEST-PASS | TestAudioInputSource.DeviceChangedCallback | test completed (time: 30ms)
Whiteboard: [retriggered]

Yes, this test is landed in bug 1238038

Flags: needinfo?(cchang)
Regressed by: 1238038

It seems we receive a "stop" callback before the expected one. The error should not affect the product code since the problem should be in the test itself or the simulated audio backend.

Set release status flags based on info from the regressing bug 1238038

We need to wait for the stream stop called by the forced error
before calling AudioInputSource::Stop to ensure the callback order in
the test. Otherwise, the stream stop called by the forced error on the
background thread will race with the stream stop called by the
AudioInputSource::Stop in its task thread.

The problem of the intermittently unexpected callbacks can be reproduced
by adding a delay/thread-sleep in the forced-error's background thread
task. When MockCubeb runs into the error state by ForceError(), it
will create a background-thread task to stop the cubeb stream. On the
other hand, when AuidioInputSource::Stop is called, it will create a
task to stop the cubeb stream first and then destroy the cubeb stream,
on its own task thread. Most of time, when AudioInputSource::Stop is
called, the underlying cubeb stream has been stopped by the brackground
task, so the MockCubebStream won't fire the stopped-state callback.
MockCubeb::StopStream in MockCubebStream::Stop() called by
AudioInputSource::Stop() will return a CUBEB_ERROR in this case
since no stream needs to be stopped, and so no callback need to be
fired.

However, in rare cases, the stream stop on the AudioInputSource's task
thread finishes before the one in the background thread. Hence, the
MockCubebStream::Stop() called by AudioInputSource::Stop() can stop
the stream successfully and then fire a stopped state callback.

We don't care what thread stop the stream in
TestAudioInputSource.ErrorCallback test, as long as the error-state
cabllback can be forwarded correctly and the stream can be destroyed in
the end. To avoid the racy stream stop calls between the background
thread and the task thread, we don't call AudioInputSource::Stop()
until stream is stopped in background thread.

Attachment #9273735 - Attachment description: Bug 1765312 - Wait for rror stop refore stopping AudioInputSource → Bug 1765312 - Wait for error stop before AudioInputSource::Stop()
Assignee: nobody → cchang
Has Regression Range: --- → yes
Pushed by cchang@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/8d2934632295
Wait for error stop before AudioInputSource::Stop() r=padenot
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
Target Milestone: --- → 101 Branch
See Also: → 1765230
See Also: → 1775317
See Also: → 1846191
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: