Intermittent dom/media/webaudio/test/test_webAudio_muteTab.html | Unmuting wasn't effective
Categories
(Core :: Web Audio, defect, P5)
Tracking
()
Tracking | Status | |
---|---|---|
firefox94 | --- | fixed |
People
(Reporter: intermittent-bug-filer, Assigned: padenot)
References
Details
(Keywords: intermittent-failure)
Attachments
(5 files)
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
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 4•3 years ago
|
||
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.
Comment 5•3 years ago
|
||
Comment 6•3 years ago
|
||
Comment 7•3 years ago
|
||
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.
Comment 8•3 years ago
|
||
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
Comment 9•3 years ago
|
||
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.
Comment 10•3 years ago
|
||
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.
Comment 11•3 years ago
|
||
padenot, is there anything in the cubeb logging that I should look for. I can post logs here if that would help.
Comment hidden (Intermittent Failures Robot) |
Assignee | ||
Comment 13•3 years ago
|
||
(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.
Comment 14•3 years ago
|
||
Comment 15•3 years ago
|
||
Comment 17•3 years ago
|
||
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 | ||
Comment 18•3 years ago
|
||
Updated•3 years ago
|
Comment 19•3 years ago
|
||
I've run some tests here with padenot's patch, and after commenting out the other 2, it seems that echoCancellation is the culprit.
Comment 20•3 years ago
|
||
Pushed by padenot@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/6b7f83a06cd0 Disable audio input processing when checking tab muting. r=pehrsons
Comment 21•3 years ago
|
||
bugherder |
Assignee | ||
Updated•3 years ago
|
Comment hidden (Intermittent Failures Robot) |
Description
•