Closed Bug 2050519 Opened 2 months ago Closed 12 days ago

Frequent TestWebrtcVideoEncoderFactory.RacyGmpPluginForwards | Expected equality of these values: | single tracking bug

Categories

(Core :: Audio/Video: GMP, defect, P2)

defect

Tracking

()

RESOLVED FIXED
156 Branch
Tracking Status
firefox-esr115 --- wontfix
firefox-esr140 --- wontfix
firefox-esr153 --- wontfix
firefox152 --- wontfix
firefox153 --- wontfix
firefox154 --- wontfix
firefox155 --- wontfix
firefox156 --- fixed

People

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

References

Details

(Keywords: intermittent-failure, regression)

Attachments

(3 files)

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


[task 2026-06-25T14:13:09.073+00:00] 14:13:09     INFO - TEST-PASS | TestWebrtcVideoDecoderFactory.RacyGmpPluginForwards | took 309ms
[task 2026-06-25T14:13:09.074+00:00] 14:13:09     INFO - SUITE-END | took 0s
[task 2026-06-25T14:13:09.081+00:00] 14:13:09     INFO -  Finished running GTest tests.
[task 2026-06-25T14:13:09.092+00:00] 14:13:09     INFO - gtest.TestWebrtcVideoDecoderFactory | process wait complete, returncode=0
[task 2026-06-25T14:13:09.092+00:00] 14:13:09     INFO -  mozcrash checking /opt/worker/tasks/task_178239485218235/build/tests/gtest for minidumps...
[task 2026-06-25T14:13:09.176+00:00] 14:13:09     INFO -  *** You are running in headless mode.
[task 2026-06-25T14:13:09.277+00:00] 14:13:09     INFO -  Running GTest tests...
[task 2026-06-25T14:13:09.561+00:00] 14:13:09     INFO -  Setting up crash reporting
[task 2026-06-25T14:13:09.580+00:00] 14:13:09     INFO - SUITE-START | Running 0 tests
[task 2026-06-25T14:13:09.581+00:00] 14:13:09     INFO - TEST-START | TestWebrtcVideoEncoderFactory.RacyGmpPluginForwards
[task 2026-06-25T14:13:09.592+00:00] 14:13:09     INFO - TEST-UNEXPECTED-FAIL | TestWebrtcVideoEncoderFactory.RacyGmpPluginForwards | Expected equality of these values:
[task 2026-06-25T14:13:09.592+00:00] 14:13:09     INFO -   h264GmpSupport
[task 2026-06-25T14:13:09.592+00:00] 14:13:09     INFO -     Which is: 8-byte object <00-00 00-00 00-00 00-00>
[task 2026-06-25T14:13:09.592+00:00] 14:13:09     INFO -   media::EncodeSupportSet{media::EncodeSupport::SoftwareEncode}
[task 2026-06-25T14:13:09.592+00:00] 14:13:09     INFO -     Which is: 8-byte object <01-00 00-00 00-00 00-00>
[task 2026-06-25T14:13:09.592+00:00] 14:13:09     INFO - 
[task 2026-06-25T14:13:09.592+00:00] 14:13:09     INFO - ./../../../../../checkouts/gecko/dom/media/gtest/TestWebrtcCodecFactory.cpp:83
[task 2026-06-25T14:13:09.593+00:00] 14:13:09     INFO - TEST-UNEXPECTED-FAIL | TestWebrtcVideoEncoderFactory.RacyGmpPluginForwards | expected PASS
[task 2026-06-25T14:13:09.593+00:00] 14:13:09     INFO - TEST-INFO took 11ms
[task 2026-06-25T14:13:09.593+00:00] 14:13:09     INFO - SUITE-END | took 0s
[task 2026-06-25T14:13:09.600+00:00] 14:13:09     INFO -  Finished running GTest tests.
[task 2026-06-25T14:13:09.632+00:00] 14:13:09     INFO - gtest.TestWebrtcVideoEncoderFactory | process wait complete, returncode=1
[task 2026-06-25T14:13:09.633+00:00] 14:13:09     INFO -  mozcrash checking /opt/worker/tasks/task_178239485218235/build/tests/gtest for minidumps...
[task 2026-06-25T14:13:09.633+00:00] 14:13:09    ERROR - gtest.TestWebrtcVideoEncoderFactory | test failed with return code 1
[task 2026-06-25T14:13:09.637+00:00] 14:13:09     INFO - rungtests.py exits with code 1
[task 2026-06-25T14:13:09.658+00:00] 14:13:09     INFO - Return code: 1
[task 2026-06-25T14:13:09.658+00:00] 14:13:09  WARNING - Got 2 unexpected statuses
[task 2026-06-25T14:13:09.658+00:00] 14:13:09     INFO - TinderboxPrint: gtest-gtest<br/>4547/<em class="testfail">2</em>/3
[task 2026-06-25T14:13:09.658+00:00] 14:13:09  WARNING - setting return code to 2
[task 2026-06-25T14:13:09.658+00:00] 14:13:09     INFO - The gtest suite: gtest ran with return status: FAILURE
[task 2026-06-25T14:13:09.659+00:00] 14:13:09     INFO - Running post-action listener: _package_coverage_data
[task 2026-06-25T14:13:09.659+00:00] 14:13:09     INFO - Running post-action listener: _resource_record_post_action
[task 2026-06-25T14:13:09.659+00:00] 14:13:09     INFO - Running post-action listener: process_java_coverage_data
[task 2026-06-25T14:13:09.659+00:00] 14:13:09     INFO - [mozharness: 2026-06-25 14:13:09.659268Z] Finished run-tests step (success)
[task 2026-06-25T14:13:09.659+00:00] 14:13:09     INFO - [mozharness: 2026-06-25 14:13:09.659308Z] Running uninstall step.
[task 2026-06-25T14:13:09.659+00:00] 14:13:09     INFO - Running pre-action listener: _resource_record_pre_action
[task 2026-06-25T14:13:09.659+00:00] 14:13:09     INFO - Running main action method: uninstall
[task 2026-06-25T14:13:09.659+00:00] 14:13:09     INFO - Skipping uninstall for non-MSIX test
[task 2026-06-25T14:13:09.659+00:00] 14:13:09     INFO - Running post-action listener: _resource_record_post_action
[task 2026-06-25T14:13:09.659+00:00] 14:13:09     INFO - [mozharness: 2026-06-25 14:13:09.659527Z] Finished uninstall step (success)
[task 2026-06-25T14:13:09.660+00:00] 14:13:09     INFO - Running post-run listener: _resource_record_post_run
[task 2026-06-25T14:13:09.813+00:00] 14:13:09     INFO - instance_metadata.json not found; unable to determine instance type
[task 2026-06-25T14:13:09.833+00:00] 14:13:09     INFO - Validating Perfherder data against /opt/worker/tasks/task_178239485218235/mozharness/external_tools/performance-artifact-schema.json
[task 2026-06-25T14:13:09.835+00:00] 14:13:09     INFO - PERFHERDER_DATA: {"framework": {"name": "job_resource_usage"}, "suites": [{"name": "gtest.gtest.overall", "extraOptions": ["buildbot-unknown"], "subtests": [{"name": "cpu_percent", "value": 18.910298067758454}, {"name": "io_write_bytes", "value": 1291821056}, {"name": "io.read_bytes", "value": 1750843392}, {"name": "io_write_time", "value": 4788}, {"name": "io_read_time", "value": 45491}]}, {"name": "gtest.gtest.start-pulseaudio", "subtests": [{"name": "time", "value": 0.00020499600009316055}, {"name": "cpu_percent", "value": 0}]}, {"name": "gtest.gtest.unlock-keyring", "subtests": [{"name": "time", "value": 9.516700015410606e-05}, {"name": "cpu_percent", "value": 0}]}, {"name": "gtest.gtest.install", "subtests": [{"name": "time", "value": 29.008573225999953}, {"name": "cpu_percent", "value": 17.42575757575758}]}, {"name": "gtest.gtest.stage-files", "subtests": [{"name": "time", "value": 0.14028846899987002}, {"name": "cpu_percent", "value": 13.700000000000001}]}, {"name": "gtest.gtest.run-tests", "subtests": [{"name": "time", "value": 745.98151755}, {"name": "cpu_percent", "value": 18.970058519018703}]}, {"name": "gtest.gtest.uninstall", "subtests": [{"name": "time", "value": 0.00011461200006124272}, {"name": "cpu_percent", "value": 0}]}]}
[task 2026-06-25T14:13:09.836+00:00] 14:13:09     INFO - Total resource usage - Wall time: 775s; CPU: Can't collect data; Read bytes: 1750843392; Write bytes: 1291821056; Read time: 45491; Write time: 4788
[task 2026-06-25T14:13:09.836+00:00] 14:13:09     INFO - Total resource usage - Wall time: 775s; CPU: Can't collect data; Read bytes: 1750843392; Write bytes: 1291821056; Read time: 45491; Write time: 4788
[task 2026-06-25T14:13:09.836+00:00] 14:13:09     INFO - TinderboxPrint: I/O read bytes / time<br/>1,750,843,392 / 45,491
[task 2026-06-25T14:13:09.836+00:00] 14:13:09     INFO - TinderboxPrint: I/O write bytes / time<br/>1,291,821,056 / 4,788
[task 2026-06-25T14:13:09.836+00:00] 14:13:09     INFO - TinderboxPrint: CPU idle<br/>7,508.8 (81.0%)
[task 2026-06-25T14:13:09.836+00:00] 14:13:09     INFO - TinderboxPrint: CPU system<br/>742.5 (8.0%)
[task 2026-06-25T14:13:09.836+00:00] 14:13:09     INFO - TinderboxPrint: CPU user<br/>1,016.7 (11.0%)
[task 2026-06-25T14:13:09.836+00:00] 14:13:09     INFO - TinderboxPrint: Swap in / out<br/>669,433,856 / 0
[task 2026-06-25T14:13:09.838+00:00] 14:13:09     INFO - start-pulseaudio - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2026-06-25T14:13:09.839+00:00] 14:13:09     INFO - unlock-keyring - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2026-06-25T14:13:09.842+00:00] 14:13:09     INFO - install - Wall time: 29s; CPU: 17%; Read bytes: 517463040; Write bytes: 386940928; Read time: 29725; Write time: 608
[task 2026-06-25T14:13:09.844+00:00] 14:13:09     INFO - stage-files - Wall time: 0s; CPU: 14%; Read bytes: 491520; Write bytes: 225017856; Read time: 80; Write time: 376
[task 2026-06-25T14:13:09.897+00:00] 14:13:09     INFO - run-tests - Wall time: 746s; CPU: 19%; Read bytes: 1614086144; Write bytes: 679833600; Read time: 41639; Write time: 3804
[task 2026-06-25T14:13:09.900+00:00] 14:13:09     INFO - uninstall - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2026-06-25T14:13:10.761+00:00] 14:13:10  WARNING - returning nonzero exit status 2
[taskcluster 2026-06-25T14:13:10.885Z]    Exit Code: 2
[taskcluster 2026-06-25T14:13:10.885Z]    User Time: 11m44.908882s
[taskcluster 2026-06-25T14:13:10.885Z]  Kernel Time: 5m47.524064s
[taskcluster 2026-06-25T14:13:10.885Z]    Wall Time: 13m57.94327s
[taskcluster 2026-06-25T14:13:10.885Z]       Result: FAILED
[taskcluster 2026-06-25T14:13:10.885Z] === Task Finished ===
[taskcluster 2026-06-25T14:13:10.885Z] Task Duration: 13m57.948089s
[taskcluster 2026-06-25T14:13:11.164Z] Uploading artifact public/build/perfherder-data-mozharness-actions.json from file /opt/worker/tasks/task_178239485218235/public/build/perfherder-data-mozharness-actions.json with content encoding "gzip", mime type "application/json" and expiry 2027-06-25T13:46:26.737Z
[taskcluster 2026-06-25T14:13:11.495Z] Uploading artifact public/logs/localconfig.json from file /opt/worker/tasks/task_178239485218235/logs/localconfig.json with content encoding "gzip", mime type "application/json" and expiry 2027-06-25T13:46:26.737Z
[taskcluster 2026-06-25T14:13:11.826Z] Uploading artifact public/test_info/perfherder-data-gtest.json from file /opt/worker/tasks/task_178239485218235/build/blobber_upload_dir/perfherder-data-gtest.json with content encoding "gzip", mime type "application/json" and expiry 2027-06-25T13:46:26.737Z
[taskcluster 2026-06-25T14:13:12.125Z] Uploading artifact public/test_info/perfherder-data-resource-usage.json from file /opt/worker/tasks/task_178239485218235/build/blobber_upload_dir/perfherder-data-resource-usage.json with content encoding "gzip", mime type "application/json" and expiry 2027-06-25T13:46:26.737Z
[taskcluster 2026-06-25T14:13:12.433Z] Uploading artifact public/test_info/profile_resource-usage.json from file /opt/worker/tasks/task_178239485218235/build/blobber_upload_dir/profile_resource-usage.json with content encoding "gzip", mime type "application/json" and expiry 2027-06-25T13:46:26.737Z
[taskcluster 2026-06-25T14:13:12.852Z] Uploading artifact public/test_info/system-info.log from file /opt/worker/tasks/task_178239485218235/build/blobber_upload_dir/system-info.log with content encoding "gzip", mime type "text/plain" and expiry 2027-06-25T13:46:26.737Z
[taskcluster 2026-06-25T14:13:13.154Z] Uploading artifact public/fetch/perfherder-data-fetch-content.json from file /opt/worker/tasks/task_178239485218235/perf/perfherder-data-fetch-content.json with content encoding "gzip", mime type "application/json" and expiry 2027-06-25T13:46:26.737Z
[taskcluster 2026-06-25T14:13:13.365Z] [mounts] Preserving cache: Moving "/opt/worker/tasks/task_178239485218235/.task-cache/pip" to "/opt/worker/cache/NegwMQsORCC5YTREM5ReAw"
[taskcluster 2026-06-25T14:13:13.366Z] [mounts] Preserving cache: Moving "/opt/worker/tasks/task_178239485218235/.task-cache/uv" to "/opt/worker/cache/KAjmBa4TTPGNM45VYcgxog"
[taskcluster 2026-06-25T14:13:13.476Z] Uploading link artifact public/logs/live.log to artifact public/logs/live_backing.log with expiry 2027-06-25T13:46:26.737Z
[taskcluster:error] exit status 2
Summary: Intermittent TestWebrtcVideoEncoderFactory.RacyGmpPluginForwards | Expected equality of these values: → Intermittent TestWebrtcVideoEncoderFactory.RacyGmpPluginForwards | Expected equality of these values: | single tracking bug
Flags: needinfo?(apehrson)
Keywords: regression
Regressed by: 2025517
Summary: Intermittent TestWebrtcVideoEncoderFactory.RacyGmpPluginForwards | Expected equality of these values: | single tracking bug → Frequent TestWebrtcVideoEncoderFactory.RacyGmpPluginForwards | Expected equality of these values: | single tracking bug

:dbaker, since you are the author of the regressor, bug 2025517, could you take a look?

For more information, please visit BugBot documentation.

Flags: needinfo?(dbaker)

I wonder if bug 2048566 may help.

Flags: needinfo?(dbaker)
Blocks: 2051008

It seems like bug 2025517 just exposed an issue rather than caused it.

Assignee: nobody → apehrson
Status: NEW → ASSIGNED
Priority: P5 → P2
No longer regressed by: 2025517
See Also: → 2025517
Component: WebRTC: Audio/Video → Audio/Video: GMP

The issue seems to be a race between setting mScannedPluginOnDisk (bug 1067216) after the calls to AddOnGMPThread which are async after Init since bug 1245789.

See Also: → 1067216
Blocks: 2048566

HasPluginForAPI() is meant to answer only once the scan of MOZ_GMP_PATH has
registered the plugins it found. Assert that, for both kinds of test plugin.

gmp-fake is queried first and has to stay first. It is described by a Chromium
manifest.json, and parsing that round trips to the main thread, so it is
registered a few tasks after the scan itself has run. Querying either of the
others first spins the event loop enough to hide the problem.

The test is kept alone in its suite so that it gets a process where nothing has
touched the GMP service yet.

EnsurePluginsOnDiskScanned() waited for the GMP thread to run a dummy runnable,
and took mScannedPluginOnDisk to mean the scan had finished. Neither is a barrier
for plugin registration: LoadFromEnvironment() sets that flag and returns while
the GMPParent::Init() promises it started are still in flight, and the plugins
those find are appended to mPlugins by later GMP thread tasks. HasPluginForAPI()
and FindPluginDirectoryForAPI() could therefore report a plugin as missing while
it was still being registered.

Wait on EnsureInitialized() instead, which is the barrier that already exists for
"LoadFromEnvironment() has completed", and drop mScannedPluginOnDisk.

On macOS and Windows, GMPParent::Init() also reads the plugin binary header to
check its architecture. That is enough extra work for the main thread to win the
race, which is why TestWebrtcVideoEncoderFactory.RacyGmpPluginForwards and
TestWebrtcVideoDecoderFactory.RacyGmpPluginForwards fail there but never on
Linux. Also fixes bug 2051008.

Attachment #9628296 - Attachment description: Bug 2050519 - Add a gtest covering GMP plugin visibility on the first query. r=#media-playback-reviewers! → Bug 2050519 - Add a gtest covering GMP plugin visibility on the first query. r?#media-playback-reviewers

InitializePlugins() settles mInitPromise from the GMP thread. If the thread is
joined while the scan of MOZ_GMP_PATH is still in flight, the tasks that would
have settled it are dropped, and every EnsureInitialized() caller waits forever.

Settle it from the shutdown-threads observer instead, once the thread is gone.

Attachment #9628297 - Attachment description: Bug 2050519 - Wait for GMP plugin registration before answering plugin queries. r=#media-playback-reviewers! → Bug 2050519 - Wait for GMP plugin registration before answering plugin queries. r?#media-playback-reviewers
Pushed by pehrsons@gmail.com: https://github.com/mozilla-firefox/firefox/commit/3b5e77fcb1c3 https://hg.mozilla.org/integration/autoland/rev/4ac152409203 Add a gtest covering GMP plugin visibility on the first query. r=media-playback-reviewers,azebrowski https://github.com/mozilla-firefox/firefox/commit/d6efb526a0f8 https://hg.mozilla.org/integration/autoland/rev/448513056450 Settle the GMP init promise when the GMP thread goes away. r=media-playback-reviewers,padenot https://github.com/mozilla-firefox/firefox/commit/cdab661372fc https://hg.mozilla.org/integration/autoland/rev/0eb2545c16f4 Wait for GMP plugin registration before answering plugin queries. r=media-playback-reviewers,azebrowski
Status: ASSIGNED → RESOLVED
Closed: 12 days ago
Resolution: --- → FIXED
Target Milestone: --- → 156 Branch

Since nightly and release are affected, beta will likely be affected too.
For more information, please visit BugBot documentation.

The patch landed in nightly and beta is affected.
:pehrsons, is this bug important enough to require an uplift?

For more information, please visit BugBot documentation.

Flags: needinfo?(apehrson)

This is a bug from close to the inception of GMP. In practice it seems to mainly affect GTests. It can ride.

You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: