Closed Bug 1724014 Opened 3 years ago Closed 3 years ago

Intermittent dom/media/webaudio/test/test_webAudio_muteTab.html | Unmuting wasn't effective

Categories

(Core :: Web Audio, defect, P5)

Product:
Core
Component:
Web Audio
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
94 Branch
Tracking Flags:
Tracking Status
firefox94 --- fixed

People

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

References

Details

(Keywords: intermittent-failure)

Attachments

(5 files)

passing case for pulseverbose.log
(deleted), text/plain
Details
failing case for pulseverbose.log
(deleted), text/plain
Details
failing case w/ cubeb:5 logging
(deleted), text/plain
Details
passing case w/ cubeb:5 logging
(deleted), text/plain
Details
Bug 1724014 - Disable audio input processing when checking tab muting. r?pehrsons
(deleted), text/x-phabricator-request
Details

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

[task 2021-08-04T14:36:28.092Z] 14:36:28     INFO - TEST-OK | dom/media/webaudio/test/test_mediaStreamAudioSourceNodeNoGC.html | took 13001ms
[task 2021-08-04T14:36:28.449Z] 14:36:28     INFO - TEST-START | dom/media/webaudio/test/test_webAudio_muteTab.html
[task 2021-08-04T14:36:29.323Z] 14:36:29     INFO - GECKO(4342) | TEST DEVICES: Got loopback audio: Monitor of Null Output
[task 2021-08-04T14:36:29.326Z] 14:36:29     INFO - GECKO(4342) | TEST DEVICES: Got loopback video: Dummy video device (0x0000)
[task 2021-08-04T14:36:29.633Z] 14:36:29     INFO - GECKO(4342) | TEST DEVICES: Got loopback audio: Monitor of Null Output
[task 2021-08-04T14:36:29.638Z] 14:36:29     INFO - GECKO(4342) | TEST DEVICES: Got loopback video: Dummy video device (0x0000)
[task 2021-08-04T14:36:35.518Z] 14:36:35     INFO - TEST-INFO | started process screentopng
[task 2021-08-04T14:36:35.829Z] 14:36:35     INFO - TEST-INFO | screentopng: exit 0
[task 2021-08-04T14:36:35.830Z] 14:36:35     INFO - Buffered messages logged at 14:36:29
[task 2021-08-04T14:36:35.830Z] 14:36:35     INFO - TEST-PASS | dom/media/webaudio/test/test_webAudio_muteTab.html | A valid string reason is expected 
[task 2021-08-04T14:36:35.830Z] 14:36:35     INFO - TEST-PASS | dom/media/webaudio/test/test_webAudio_muteTab.html | Reason cannot be empty 
[task 2021-08-04T14:36:35.831Z] 14:36:35     INFO - Call getUserMedia for {"audio":true}
[task 2021-08-04T14:36:35.832Z] 14:36:35     INFO - Buffered messages logged at 14:36:30
[task 2021-08-04T14:36:35.832Z] 14:36:35     INFO - TEST-PASS | dom/media/webaudio/test/test_webAudio_muteTab.html | One audio track shall be present 
[task 2021-08-04T14:36:35.832Z] 14:36:35     INFO - TEST-PASS | dom/media/webaudio/test/test_webAudio_muteTab.html | Track kind should be audio 
[task 2021-08-04T14:36:35.832Z] 14:36:35     INFO - TEST-PASS | dom/media/webaudio/test/test_webAudio_muteTab.html | Track id should be defined 
[task 2021-08-04T14:36:35.833Z] 14:36:35     INFO - TEST-PASS | dom/media/webaudio/test/test_webAudio_muteTab.html | Track should not be muted 
[task 2021-08-04T14:36:35.836Z] 14:36:35     INFO - TEST-PASS | dom/media/webaudio/test/test_webAudio_muteTab.html | No video tracks shall be present 
[task 2021-08-04T14:36:35.837Z] 14:36:35     INFO - TEST-FAIL | dom/media/webaudio/test/test_webAudio_muteTab.html | The author of the test has indicated that flaky timeouts are expected.  Reason: WebRTC inherently depends on timeouts 
[task 2021-08-04T14:36:35.837Z] 14:36:35     INFO - TEST-FAIL | dom/media/webaudio/test/test_webAudio_muteTab.html | The author of the test has indicated that flaky timeouts are expected.  Reason: WebRTC inherently depends on timeouts 
[task 2021-08-04T14:36:35.837Z] 14:36:35     INFO - Buffered messages logged at 14:36:33
[task 2021-08-04T14:36:35.837Z] 14:36:35     INFO - TEST-PASS | dom/media/webaudio/test/test_webAudio_muteTab.html | Muting the tab was effective 
[task 2021-08-04T14:36:35.837Z] 14:36:35     INFO - TEST-FAIL | dom/media/webaudio/test/test_webAudio_muteTab.html | The author of the test has indicated that flaky timeouts are expected.  Reason: WebRTC inherently depends on timeouts 
[task 2021-08-04T14:36:35.837Z] 14:36:35     INFO - TEST-FAIL | dom/media/webaudio/test/test_webAudio_muteTab.html | The author of the test has indicated that flaky timeouts are expected.  Reason: WebRTC inherently depends on timeouts 
[task 2021-08-04T14:36:35.837Z] 14:36:35     INFO - Buffered messages finished
[task 2021-08-04T14:36:35.838Z] 14:36:35     INFO - TEST-UNEXPECTED-FAIL | dom/media/webaudio/test/test_webAudio_muteTab.html | Unmuting wasn't effective 
[task 2021-08-04T14:36:35.838Z] 14:36:35     INFO - SimpleTest.ok@https://example.com/tests/SimpleTest/SimpleTest.js:417:16
[task 2021-08-04T14:36:35.838Z] 14:36:35     INFO - @https://example.com/tests/dom/media/webaudio/test/test_webAudio_muteTab.html:76:15
[task 2021-08-04T14:36:35.838Z] 14:36:35     INFO - waitForAnalysisSuccess@https://example.com/tests/dom/media/webaudio/test/head.js:216:15
[task 2021-08-04T14:36:35.838Z] 14:36:35     INFO - TEST-PASS | dom/media/webaudio/test/test_webAudio_muteTab.html | Test must leave no active gUM streams behind. 
[task 2021-08-04T14:36:35.838Z] 14:36:35     INFO - GECKO(4342) | MEMORY STAT | vsize 130550460MB | residentFast 333MB
[task 2021-08-04T14:36:35.838Z] 14:36:35     INFO - TEST-OK | dom/media/webaudio/test/test_webAudio_muteTab.html | took 7374ms
[task 2021-08-04T14:36:36.016Z] 14:36:36     INFO - TEST-START | Shutdown
[task 2021-08-04T14:36:36.018Z] 14:36:36     INFO - Passed:  17
[task 2021-08-04T14:36:36.019Z] 14:36:36     INFO - Failed:  1
[task 2021-08-04T14:36:36.019Z] 14:36:36     INFO - Todo:    8
[task 2021-08-04T14:36:36.031Z] 14:36:36     INFO - Mode:    e10s
[task 2021-08-04T14:36:36.032Z] 14:36:36     INFO - Slowest: 13001ms - /tests/dom/media/webaudio/test/test_mediaStreamAudioSourceNodeNoGC.html
[task 2021-08-04T14:36:36.034Z] 14:36:36     INFO - SimpleTest FINISHED
[task 2021-08-04T14:36:36.034Z] 14:36:36     INFO - TEST-INFO | Ran 1 Loops
[task 2021-08-04T14:36:36.034Z] 14:36:36     INFO - SimpleTest FINISHED
[task 2021-08-04T14:36:36.414Z] 14:36:36     INFO - GECKO(4342) | JavaScript error: resource://gre/modules/AsyncShutdown.jsm, line 575: NotFoundError: No such JSWindowActor 'SpecialPowers'
[task 2021-08-04T14:36:36.726Z] 14:36:36     INFO - GECKO(4342) | 1628087796725	Marionette	TRACE	Received observer notification quit-application
[task 2021-08-04T14:36:36.728Z] 14:36:36     INFO - GECKO(4342) | 1628087796726	Marionette	INFO	Stopped listening on port 2828
[task 2021-08-04T14:36:36.730Z] 14:36:36     INFO - GECKO(4342) | 1628087796729	Marionette	DEBUG	Marionette stopped listening
[task 2021-08-04T14:36:37.018Z] 14:36:37     INFO - GECKO(4342) | JavaScript error: resource:///modules/Interactions.jsm, line 230: NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIUserIdleService.removeIdleObserver]
[task 2021-08-04T14:36:37.080Z] 14:36:37     INFO - GECKO(4342) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-08-04T14:36:37.138Z] 14:36:37     INFO - GECKO(4342) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-08-04T14:36:37.138Z] 14:36:37     INFO - GECKO(4342) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-08-04T14:36:38.180Z] 14:36:38     INFO - GECKO(4342) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-08-04T14:36:38.183Z] 14:36:38     INFO - GECKO(4342) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-08-04T14:36:38.193Z] 14:36:38     INFO - GECKO(4342) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-08-04T14:36:42.419Z] 14:36:42     INFO - TEST-INFO | Main app process: exit 0
[task 2021-08-04T14:36:42.420Z] 14:36:42     INFO - runtests.py | Application ran for: 0:00:51.554744
[task 2021-08-04T14:36:42.421Z] 14:36:42     INFO - zombiecheck | Reading PID log: /tmp/tmpc4h1d814pidlog
[task 2021-08-04T14:36:42.421Z] 14:36:42     INFO - ==> process 4342 launched child process 4358
[task 2021-08-04T14:36:42.421Z] 14:36:42     INFO - ==> process 4342 launched child process 4429
[task 2021-08-04T14:36:42.422Z] 14:36:42     INFO - ==> process 4342 launched child process 4457
[task 2021-08-04T14:36:42.423Z] 14:36:42     INFO - ==> process 4342 launched child process 4490
[task 2021-08-04T14:36:42.423Z] 14:36:42     INFO - ==> process 4342 launched child process 4537
[task 2021-08-04T14:36:42.424Z] 14:36:42     INFO - zombiecheck | Checking for orphan process with PID: 4358
[task 2021-08-04T14:36:42.424Z] 14:36:42     INFO - zombiecheck | Checking for orphan process with PID: 4457
[task 2021-08-04T14:36:42.425Z] 14:36:42     INFO - zombiecheck | Checking for orphan process with PID: 4490
[task 2021-08-04T14:36:42.425Z] 14:36:42     INFO - zombiecheck | Checking for orphan process with PID: 4429
[task 2021-08-04T14:36:42.426Z] 14:36:42     INFO - zombiecheck | Checking for orphan process with PID: 4537
[task 2021-08-04T14:36:42.426Z] 14:36:42     INFO - Stopping web server
[task 2021-08-04T14:36:42.440Z] 14:36:42     INFO - Server shut down.
[task 2021-08-04T14:36:42.481Z] 14:36:42     INFO - Web server killed.
[task 2021-08-04T14:36:42.481Z] 14:36:42     INFO - Stopping web socket server
[task 2021-08-04T14:36:42.502Z] 14:36:42     INFO - Stopping ssltunnel
[task 2021-08-04T14:36:42.524Z] 14:36:42     INFO -  websocket/process bridge listening on port 8191
[task 2021-08-04T14:36:42.584Z] 14:36:42     INFO - Stopping websocket/process bridge
[task 2021-08-04T14:36:42.585Z] 14:36:42  WARNING - leakcheck | refcount logging is off, so leaks can't be detected!
[task 2021-08-04T14:36:42.586Z] 14:36:42     INFO - runtests.py | Running tests: end.
[task 2021-08-04T14:36:42.626Z] 14:36:42     INFO - Buffered messages finished
[task 2021-08-04T14:36:42.627Z] 14:36:42     INFO - Running manifest: dom/media/webrtc/tests/mochitests/identity/mochitest.ini
[task 2021-08-04T14:36:42.651Z] 14:36:42     INFO -  Setting pipeline to PAUSED ...
[task 2021-08-04T14:36:42.651Z] 14:36:42     INFO -  Pipeline is PREROLLING ...
[task 2021-08-04T14:36:42.654Z] 14:36:42     INFO -  Pipeline is PREROLLED ...
[task 2021-08-04T14:36:42.654Z] 14:36:42     INFO -  Setting pipeline to PLAYING ...
[task 2021-08-04T14:36:42.654Z] 14:36:42     INFO -  New clock: GstSystemClock
[task 2021-08-04T14:36:42.687Z] 14:36:42     INFO -  Got EOS from element "pipeline0".
[task 2021-08-04T14:36:42.688Z] 14:36:42     INFO -  Execution ended after 0:00:00.033488859
[task 2021-08-04T14:36:42.688Z] 14:36:42     INFO -  Setting pipeline to PAUSED ...
[task 2021-08-04T14:36:42.688Z] 14:36:42     INFO -  Setting pipeline to READY ...
[task 2021-08-04T14:36:42.689Z] 14:36:42     INFO -  (gst-launch-1.0:4610): GStreamer-CRITICAL **: 14:36:42.687: gst_object_unref: assertion '((GObject *) object)->ref_count > 0' failed
[task 2021-08-04T14:36:42.689Z] 14:36:42     INFO -  Setting pipeline to NULL ...
[task 2021-08-04T14:36:42.689Z] 14:36:42     INFO -  Freeing pipeline ...
[task 2021-08-04T14:36:42.723Z] 14:36:42     INFO - INFO | runtests.py | TSan using symbolizer at /builds/worker/workspace/build/application/firefox/llvm-symbolizer
[task 2021-08-04T14:36:43.455Z] 14:36:43     INFO - PID 4626 | pk12util: PKCS12 IMPORT SUCCESSFUL
[task 2021-08-04T14:36:43.492Z] 14:36:43     INFO - INFO | runtests.py | TSan using symbolizer at /builds/worker/workspace/build/application/firefox/llvm-symbolizer
[task 2021-08-04T14:36:43.492Z] 14:36:43     INFO - INFO | runtests.py | TSan using symbolizer at /builds/worker/workspace/build/application/firefox/llvm-symbolizer
[task 2021-08-04T14:36:43.497Z] 14:36:43     INFO - MochitestServer : launching ['/builds/worker/workspace/build/tests/bin/xpcshell', '-g', '/builds/worker/workspace/build/application/firefox', '-f', '/builds/worker/workspace/build/tests/bin/components/httpd.js', '-e', "const _PROFILE_PATH = '/tmp/tmphdtywe3u.mozrunner'; const _SERVER_PORT = '8888'; const _SERVER_ADDR = '127.0.0.1'; const _TEST_PREFIX = undefined; const _DISPLAY_RESULTS = false;", '-f', '/builds/worker/workspace/build/tests/mochitest/server.js']
[task 2021-08-04T14:36:43.498Z] 14:36:43     INFO - runtests.py | Server pid: 4629
[task 2021-08-04T14:36:43.504Z] 14:36:43     INFO - runtests.py | Websocket server pid: 4632
[task 2021-08-04T14:36:43.510Z] 14:36:43     INFO - runtests.py | websocket/process bridge pid: 4636
[task 2021-08-04T14:36:44.014Z] 14:36:44     INFO - INFO | runtests.py | TSan using symbolizer at /builds/worker/workspace/build/application/firefox/llvm-symbolizer
[task 2021-08-04T14:36:44.019Z] 14:36:44     INFO - runtests.py | SSL tunnel pid: 4647
[task 2021-08-04T14:36:44.120Z] 14:36:44     INFO - runtests.py | Running with scheme: http
[task 2021-08-04T14:36:44.121Z] 14:36:44     INFO - runtests.py | Running with e10s: True
[task 2021-08-04T14:36:44.121Z] 14:36:44     INFO - runtests.py | Running with fission: False
[task 2021-08-04T14:36:44.122Z] 14:36:44     INFO - runtests.py | Running with cross-origin iframes: False
[task 2021-08-04T14:36:44.123Z] 14:36:44     INFO - runtests.py | Running with serviceworker_e10s: True
[task 2021-08-04T14:36:44.123Z] 14:36:44     INFO - runtests.py | Running with socketprocess_e10s: False
[task 2021-08-04T14:36:44.123Z] 14:36:44     INFO - runtests.py | Running tests: start.
[task 2021-08-04T14:36:44.123Z] 14:36:44     INFO - 
[task 2021-08-04T14:36:44.143Z] 14:36:44     INFO - Application command: /builds/worker/workspace/build/application/firefox/firefox -marionette -foreground -profile /tmp/tmphdtywe3u.mozrunner
[task 2021-08-04T14:36:44.149Z] 14:36:44     INFO - runtests.py | Application pid: 4659
[task 2021-08-04T14:36:44.149Z] 14:36:44     INFO - TEST-INFO | started process GECKO(4659)
[task 2021-08-04T14:36:49.766Z] 14:36:49     INFO - GECKO(4659) | 1628087809765	Marionette	INFO	Marionette enabled
[task 2021-08-04T14:36:50.679Z] 14:36:50     INFO - GECKO(4659) | 1628087810678	Marionette	TRACE	Received observer notification toplevel-window-ready
[task 2021-08-04T14:37:04.855Z] 14:37:04     INFO - GECKO(4659) | console.warn: SearchSettings: "get: No settings file exists, new profile?" (new NotFoundError("Could not open the file at /tmp/tmphdtywe3u.mozrunner/search.json.mozlz4", (void 0)))
[task 2021-08-04T14:37:11.613Z] 14:37:11     INFO - GECKO(4659) | 1628087831612	Marionette	TRACE	Received observer notification marionette-startup-requested
[task 2021-08-04T14:37:11.615Z] 14:37:11     INFO - GECKO(4659) | 1628087831613	Marionette	TRACE	Waiting until startup recorder finished recording startup scripts...
[task 2021-08-04T14:37:11.863Z] 14:37:11     INFO - GECKO(4659) | 1628087831862	Marionette	TRACE	All scripts recorded.
[task 2021-08-04T14:37:11.889Z] 14:37:11     INFO - GECKO(4659) | 1628087831888	Marionette	INFO	Listening on port 2828
[task 2021-08-04T14:37:11.892Z] 14:37:11     INFO - GECKO(4659) | 1628087831891	Marionette	DEBUG	Marionette is listening
[task 2021-08-04T14:37:12.133Z] 14:37:12     INFO - GECKO(4659) | 1628087832131	Marionette	DEBUG	Accepted connection 0 from 127.0.0.1:34272
[task 2021-08-04T14:37:12.191Z] 14:37:12     INFO - GECKO(4659) | 1628087832190	Marionette	DEBUG	Accepted connection 1 from 127.0.0.1:34274
[task 2021-08-04T14:37:12.195Z] 14:37:12     INFO - GECKO(4659) | 1628087832193	Marionette	DEBUG	Closed connection 0
[task 2021-08-04T14:37:12.280Z] 14:37:12     INFO - GECKO(4659) | 1628087832279	Marionette	DEBUG	1 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2021-08-04T14:37:12.442Z] 14:37:12     INFO - GECKO(4659) | 1628087832440	Marionette	DEBUG	1 <- [1,1,null,{"sessionId":"56039ea4-7fa7-47dd-8a65-a6192267fe17","capabilities":{"browserName":"firefox","browserVersion":"92.0a ... .mozrunner","moz:shutdownTimeout":360000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"proxy":{}}}]
[task 2021-08-04T14:37:12.496Z] 14:37:12     INFO - GECKO(4659) | 1628087832495	Marionette	DEBUG	1 -> [0,2,"Addon:Install",{"path":"/tmp/tmp66867fyt.zip","temporary":false}]
[task 2021-08-04T14:37:13.439Z] 14:37:13     INFO - GECKO(4659) | 1628087833438	Marionette	DEBUG	1 <- [1,2,null,{"value":"special-powers@mozilla.org"}]
[task 2021-08-04T14:37:13.530Z] 14:37:13     INFO - GECKO(4659) | 1628087833528	Marionette	DEBUG	1 -> [0,3,"Addon:Install",{"path":"/tmp/tmp5yyjgz3j.zip","temporary":false}]
[task 2021-08-04T14:37:14.078Z] 14:37:14     INFO - GECKO(4659) | 1628087834076	Marionette	DEBUG	1 <- [1,3,null,{"value":"mochikit@mozilla.org"}]
[task 2021-08-04T14:37:14.102Z] 14:37:14     INFO - GECKO(4659) | 1628087834100	Marionette	DEBUG	1 -> [0,4,"Marionette:GetContext",{}]
[task 2021-08-04T14:37:14.105Z] 14:37:14     INFO - GECKO(4659) | 1628087834103	Marionette	DEBUG	1 <- [1,4,null,{"value":"content"}]
[task 2021-08-04T14:37:14.140Z] 14:37:14     INFO - GECKO(4659) | 1628087834111	Marionette	DEBUG	1 -> [0,5,"Marionette:SetContext",{"value":"chrome"}]
[task 2021-08-04T14:37:14.154Z] 14:37:14     INFO - GECKO(4659) | 1628087834152	Marionette	DEBUG	1 <- [1,5,null,{"value":null}]
[task 2021-08-04T14:37:14.244Z] 14:37:14     INFO - GECKO(4659) | 1628087834242	Marionette	DEBUG	1 -> [0,6,"WebDriver:ExecuteScript",{"script":"/* This Source Code Form is subject to the terms of the Mozilla Public\n * License, ... ry=%2Ftmp&cleanupCrashes=true"}],"newSandbox":true,"sandbox":"default","line":1936,"filename":"tests/mochitest/runtests.py"}]
[task 2021-08-04T14:37:14.317Z] 14:37:14     INFO - GECKO(4659) | 1628087834315	Marionette	TRACE	[7] MarionetteCommands actor created for window id 2
[task 2021-08-04T14:37:14.419Z] 14:37:14     INFO - GECKO(4659) | 1628087834418	Marionette	DEBUG	1 <- [1,6,null,{"value":null}]
[task 2021-08-04T14:37:14.521Z] 14:37:14     INFO - GECKO(4659) | 1628087834520	Marionette	DEBUG	1 -> [0,7,"Marionette:SetContext",{"value":"content"}]
[task 2021-08-04T14:37:14.528Z] 14:37:14     INFO - GECKO(4659) | 1628087834527	Marionette	DEBUG	1 <- [1,7,null,{"value":null}]
[task 2021-08-04T14:37:14.605Z] 14:37:14     INFO - GECKO(4659) | 1628087834604	Marionette	DEBUG	1 -> [0,8,"WebDriver:DeleteSession",{}]
[task 2021-08-04T14:37:14.628Z] 14:37:14     INFO - GECKO(4659) | 1628087834626	Marionette	DEBUG	1 <- [1,8,null,{"value":null}]
[task 2021-08-04T14:37:14.677Z] 14:37:14     INFO - runtests.py | Waiting for browser...
[task 2021-08-04T14:37:14.707Z] 14:37:14     INFO - GECKO(4659) | 1628087834705	Marionette	DEBUG	Closed connection 1
[task 2021-08-04T14:37:15.532Z] 14:37:15     INFO - GECKO(4659) | JavaScript error: , line 0: NotFoundError: No such JSWindowActor 'MarionetteEvents'
[task 2021-08-04T14:37:16.920Z] 14:37:16     INFO - SimpleTest START
[task 2021-08-04T14:37:16.982Z] 14:37:16     INFO - TEST-START | dom/media/webrtc/tests/mochitests/identity/test_getIdentityAssertion.html

When I looked a bit at this in pernosco I could see that audio was going to speakers properly, so muting notifications should work. However we didn't see any audio come in from the monitor device, so audio signal verification failed. It could point to a latent pulseaudio or cubeb issue, but the question then is why we've suddenly made it spike now, with bug 1654112.

I attached pulse logs for the failing and passing cases with some strategic blank lines added. The interesting bits are lines 3457-3473 in the failing case:

(  16.834|   0.001) D: [null-sink] protocol-native.c: Requesting rewind due to rewrite.
(  16.834|   0.000) D: [null-sink] module-null-sink.c: Requested to rewind 3308 bytes.
(  16.834|   0.000) D: [null-sink] sink.c: Processing rewind...
(  16.834|   0.000) D: [null-sink] sink-input.c: Have to rewind 3160 bytes on render memblockq.
(  16.834|   0.000) D: [null-sink] sink-input.c: Have to rewind 6320 bytes on implementor.
(  16.834|   0.000) D: [null-sink] source.c: Processing rewind...
(  16.834|   0.000) D: [null-sink] module-null-sink.c: Rewound 3160 bytes.
(  16.839|   0.004) D: [null-sink] sink-input.c: Requesting rewind due to corking
(  16.839|   0.000) D: [null-sink] module-null-sink.c: Requested to rewind 3308 bytes.
(  16.839|   0.000) D: [null-sink] sink.c: Processing rewind...
(  16.839|   0.000) D: [null-sink] sink-input.c: Have to rewind 2452 bytes on render memblockq.
(  16.839|   0.000) D: [null-sink] sink-input.c: Have to rewind 4904 bytes on implementor.
(  16.839|   0.000) D: [null-sink] source.c: Processing rewind...
(  16.839|   0.000) D: [null-sink] module-null-sink.c: Rewound 2452 bytes.
(  16.839|   0.000) D: [pulseaudio] module-suspend-on-idle.c: Sink null becomes idle, timeout in 5 seconds.
(  16.840|   0.001) D: [pulseaudio] module-suspend-on-idle.c: Sink null becomes idle, timeout in 5 seconds.
(  16.840|   0.000) D: [pulseaudio] core.c: Hmm, no streams around, trying to vacuum.

compared to lines 3457-3460 in the passing case:

(  16.041|   0.018) D: [null-sink] sink-input.c: Requesting rewind due to corking
(  16.041|   0.000) D: [pulseaudio] module-suspend-on-idle.c: Sink null becomes idle, timeout in 5 seconds.
(  16.043|   0.001) D: [pulseaudio] module-suspend-on-idle.c: Sink null becomes idle, timeout in 5 seconds.
(  16.043|   0.000) D: [pulseaudio] core.c: Hmm, no streams around, trying to vacuum.

Of course, as soon as I say the above, I see a failing case that doesn't match the rewind due to rewrite pattern. sigh

I wrote a different version of the test that starts with audio playing (detects noise), mutes (detects silence), then unmutes (looking for resumption of noise). In this version of the test, we never see audio resume after the unmute. When detecting noise in the new test, I'm looking for multiple, continguous non-zero results from array.reduce((acc, v) => { return acc + v; }). This may be invalid, but it seems to always work on the detecting initial noise.

Looking at the results from array.reduce((acc, v) => { return acc + v; }), what I see is that occasionally after unmuting, we'll get a short burst of noise-indicating values for a handful of checks, before the results fall back to zeros.

padenot, is there anything in the cubeb logging that I should look for. I can post logs here if that would help.

Flags: needinfo?(padenot)

(In reply to Michael Froman [:mjf] from comment #11)

padenot, is there anything in the cubeb logging that I should look for. I can post logs here if that would help.

Generally with cubeb:5 you'll see a line for each audio callback, indicating that the stream is running (you'll see different lines for input and for output). Please attach logs for me to have a look at, from a both a passing and failing run on the same configuration, I think that would be the best.

Flags: needinfo?(padenot)

See attached logs with cubeb:5 logging enabled.

Flags: needinfo?(padenot)

I've hacked in some cubeb-pulse logging and I can see that after unmuting, both push_input_data and pull_input_data start seeing non-zero values soon after the unmute. If there is additional logging you'd like to see during a test run, please let me know. For the record, this was just doing a simplistic sum of all the values in the buffer at that point.

Assignee: nobody → padenot
Status: NEW → ASSIGNED

I've run some tests here with padenot's patch, and after commenting out the other 2, it seems that echoCancellation is the culprit.

Pushed by padenot@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/6b7f83a06cd0
Disable audio input processing when checking tab muting. r=pehrsons

https://hg.mozilla.org/mozilla-central/rev/6b7f83a06cd0

Status: ASSIGNED → RESOLVED
Closed: 3 years ago
status-firefox94: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → 94 Branch
Flags: needinfo?(padenot)
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: