Perma Linux TEST-UNEXPECTED-FAIL | browser/components/shell/test/browser_headless_screenshot_3.js | Test timed out when Gecko 154 merges to Beta on 2026-07-20
Categories
(WebExtensions :: General, defect)
Tracking
(firefox-esr115 unaffected, firefox-esr140 unaffected, firefox-esr153 unaffected, firefox152 unaffected, firefox153 unaffected, firefox154+ verified)
| Tracking | Status | |
|---|---|---|
| firefox-esr115 | --- | unaffected |
| firefox-esr140 | --- | unaffected |
| firefox-esr153 | --- | unaffected |
| firefox152 | --- | unaffected |
| firefox153 | --- | unaffected |
| firefox154 | + | verified |
People
(Reporter: imoraru, Assigned: robwu)
References
(Blocks 1 open bug, Regression)
Details
(Keywords: regression, Whiteboard: [addons-jira])
Attachments
(1 file)
[Tracking Requested - why for this release]:
[task 2026-07-01T11:24:53.217+00:00] 11:24:53 INFO - TEST-START | browser/components/shell/test/browser_headless_screenshot_3.js
[task 2026-07-01T11:24:53.240+00:00] 11:24:53 INFO - GECKO(32559) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmp_6dt2u4x.mozrunner/runtests_leaks_tab_pid32912.log
[task 2026-07-01T11:24:53.241+00:00] 11:24:53 INFO - GECKO(32559) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmp_6dt2u4x.mozrunner/runtests_leaks_tab_pid32912.log
[task 2026-07-01T11:24:53.283+00:00] 11:24:53 INFO - GECKO(32559) | *** You are running in headless mode.
[task 2026-07-01T11:24:53.540+00:00] 11:24:53 INFO - GECKO(32559) | >>> expected exactly one URL when using `screenshot`
[task 2026-07-01T11:24:53.576+00:00] 11:24:53 INFO - GECKO(32559) | >>> WARNING: A blocker encountered an error while we were waiting.
[task 2026-07-01T11:24:53.577+00:00] 11:24:53 INFO - GECKO(32559) | Blocker: maybeInstallBuiltinAddon: default-theme@mozilla.org
[task 2026-07-01T11:24:53.578+00:00] 11:24:53 INFO - GECKO(32559) | Phase: quit-application
[task 2026-07-01T11:24:53.578+00:00] 11:24:53 INFO - GECKO(32559) | State: (none)
[task 2026-07-01T11:24:53.579+00:00] 11:24:53 INFO - GECKO(32559) | WARNING: Error: XPIProvider can't start bootstrap scope for default-theme@mozilla.org after shutdown was already granted
[task 2026-07-01T11:24:53.579+00:00] 11:24:53 INFO - GECKO(32559) | WARNING: startup@resource://gre/modules/addons/XPIProvider.sys.mjs:2196:17
[task 2026-07-01T11:24:53.580+00:00] 11:24:53 INFO - GECKO(32559) | _install@resource://gre/modules/addons/XPIProvider.sys.mjs:2281:18
[task 2026-07-01T11:24:53.580+00:00] 11:24:53 INFO - GECKO(32559) | install@resource://gre/modules/addons/XPIProvider.sys.mjs:2270:17
[task 2026-07-01T11:24:53.581+00:00] 11:24:53 INFO - GECKO(32559) | _activateAddon@resource://gre/modules/addons/XPIInstall.sys.mjs:4980:23
[task 2026-07-01T11:24:53.581+00:00] 11:24:53 INFO - GECKO(32559) | async*installBuiltinAddon@resource://gre/modules/addons/XPIInstall.sys.mjs:4896:16
[task 2026-07-01T11:24:53.582+00:00] 11:24:53 INFO - GECKO(32559) | async*XPIProvider[meth]@resource://gre/modules/addons/XPIProvider.sys.mjs:3655:39
[task 2026-07-01T11:24:53.583+00:00] 11:24:53 INFO - GECKO(32559) | maybeInstallBuiltinAddon@resource://gre/modules/addons/XPIProvider.sys.mjs:3300:26
[task 2026-07-01T11:24:53.583+00:00] 11:24:53 INFO - GECKO(32559) | startup@resource://gre/modules/addons/XPIProvider.sys.mjs:2786:14
[task 2026-07-01T11:24:53.584+00:00] 11:24:53 INFO - GECKO(32559) | callProvider@resource://gre/modules/AddonManager.sys.mjs:282:31
[task 2026-07-01T11:24:53.584+00:00] 11:24:53 INFO - GECKO(32559) | _startProvider@resource://gre/modules/AddonManager.sys.mjs:589:17
[task 2026-07-01T11:24:53.585+00:00] 11:24:53 INFO - GECKO(32559) | startup@resource://gre/modules/AddonManager.sys.mjs:804:14
[task 2026-07-01T11:24:53.585+00:00] 11:24:53 INFO - GECKO(32559) | startup@resource://gre/modules/AddonManager.sys.mjs:3776:26
[task 2026-07-01T11:24:53.586+00:00] 11:24:53 INFO - GECKO(32559) | observe@resource://gre/modules/amManager.sys.mjs:58:29
[task 2026-07-01T11:24:53.587+00:00] 11:24:53 INFO - GECKO(32559) | JavaScript error: resource://gre/modules/addons/XPIProvider.sys.mjs, line 2196: Error: XPIProvider can't start bootstrap scope for default-theme@mozilla.org after shutdown was already granted
[task 2026-07-01T11:24:53.588+00:00] 11:24:53 INFO - GECKO(32559) | JavaScript error: resource://gre/modules/addons/XPIProvider.sys.mjs, line 2196: Error: XPIProvider can't start bootstrap scope for default-theme@mozilla.org after shutdown was already granted
[task 2026-07-01T11:24:53.589+00:00] 11:24:53 INFO - GECKO(32559) | JavaScript error: resource://gre/modules/addons/XPIProvider.sys.mjs, line 2196: Error: XPIProvider can't start bootstrap scope for default-theme@mozilla.org after shutdown was already granted
[task 2026-07-01T11:25:03.598+00:00] 11:25:03 INFO - GECKO(32559) | >>> WARNING: At least one completion condition is taking too long to complete. Conditions: [{"name":"Extension startup: newtab@mozilla.org","state":{"state":"Startup: Run manifest, asyncEmitManifestEntry(\"background\")"},"filename":"resource://gre/modules/addons/XPIProvider.sys.mjs","lineNumber":2841,"stack":["resource://gre/modules/addons/XPIProvider.sys.mjs:startup:2841","resource://gre/modules/AddonManager.sys.mjs:callProvider:282","resource://gre/modules/AddonManager.sys.mjs:_startProvider:589","resource://gre/modules/AddonManager.sys.mjs:startup:804","resource://gre/modules/AddonManager.sys.mjs:startup:3776","resource://gre/modules/amManager.sys.mjs:observe:58"]},{"name":"XPIProvider shutdown","state":"Awaiting startup promises","filename":"resource://gre/modules/addons/XPIProvider.sys.mjs","lineNumber":2871,"stack":["resource://gre/modules/addons/XPIProvider.sys.mjs:startup:2871","resource://gre/modules/AddonManager.sys.mjs:callProvider:282","resource://gre/modules/AddonManager.sys.mjs:_startProvider:589","resource://gre/modules/AddonManager.sys.mjs:startup:804","resource://gre/modules/AddonManager.sys.mjs:startup:3776","resource://gre/modules/amManager.sys.mjs:observe:58"]}] Barrier: quit-application
[taskcluster 2026-07-01T11:25:13.964Z] [taskcluster-proxy] Successfully refreshed taskcluster-proxy credentials: task-client/DhJVfB3PRpeUkl094RMZPA/0/on/us-central1-c/2755670472055672034/until/1782906313.905
[task 2026-07-01T11:25:38.632+00:00] 11:25:38 INFO - TEST-INFO | started process screentopng
[task 2026-07-01T11:25:38.716+00:00] 11:25:38 INFO - TEST-INFO | screentopng: exit 0
[task 2026-07-01T11:25:38.716+00:00] 11:25:38 INFO - Buffered messages logged at 11:24:53
[task 2026-07-01T11:25:38.717+00:00] 11:25:38 INFO - Entering test
[task 2026-07-01T11:25:38.717+00:00] 11:25:38 INFO - Buffered messages finished
[task 2026-07-01T11:25:38.718+00:00] 11:25:38 INFO - TEST-UNEXPECTED-FAIL | browser/components/shell/test/browser_headless_screenshot_3.js | Test timed out
[task 2026-07-01T11:25:38.719+00:00] 11:25:38 INFO - TEST-UNEXPECTED-TIMEOUT | browser/components/shell/test/browser_headless_screenshot_3.js | Test timed out
[task 2026-07-01T11:25:38.719+00:00] 11:25:38 INFO - TEST-INFO took 45416ms
[task 2026-07-01T11:25:38.719+00:00] 11:25:38 INFO - GECKO(32559) | Completed ShutdownLeaks collections in process 32559
[task 2026-07-01T11:25:38.720+00:00] 11:25:38 INFO - TEST-START | Shutdown
[task 2026-07-01T11:25:38.720+00:00] 11:25:38 INFO - Browser Chrome Test Summary
[task 2026-07-01T11:25:38.721+00:00] 11:25:38 INFO - Passed: 0
[task 2026-07-01T11:25:38.721+00:00] 11:25:38 INFO - Failed: 1
[task 2026-07-01T11:25:38.722+00:00] 11:25:38 INFO - Todo: 0
[task 2026-07-01T11:25:38.722+00:00] 11:25:38 INFO - Mode: e10s
[task 2026-07-01T11:25:38.723+00:00] 11:25:38 INFO - *** End BrowserChrome Test Results ***
[task 2026-07-01T11:25:38.923+00:00] 11:25:38 INFO - GECKO(32559) | 1782905138921 Marionette TRACE Received observer notification quit-application
[task 2026-07-01T11:25:38.923+00:00] 11:25:38 INFO - GECKO(32559) | 1782905138922 Marionette TRACE Application is shutting down with reason: "shutdown"
[task 2026-07-01T11:25:38.924+00:00] 11:25:38 INFO - GECKO(32559) | 1782905138922 Marionette INFO Stopped listening on port 2828
[task 2026-07-01T11:25:38.942+00:00] 11:25:38 INFO - GECKO(32559) | 1782905138940 Marionette DEBUG Marionette stopped listening
[task 2026-07-01T11:25:39.047+00:00] 11:25:39 INFO - GECKO(32559) | 1782905139046 Marionette TRACE Received observer notification xpcom-shutdown
[task 2026-07-01T11:25:39.051+00:00] 11:25:39 INFO - GECKO(32559) | 1782905139050 Marionette TRACE Received observer notification xpcom-shutdown-threads
[task 2026-07-01T11:25:54.573+00:00] 11:25:54 INFO - GECKO(32559) | [Parent 32921, Main Thread] ###!!! ABORT: file resource://gre/modules/addons/XPIProvider.sys.mjs:2841
[task 2026-07-01T11:25:54.573+00:00] 11:25:54 INFO - GECKO(32559) | ExceptionHandler::GenerateDump attempting to generate:/tmp/headless_test_screenshot_profile/minidumps/37f8551a-7ae1-f6a1-35a4-067bdfea5103.dmp
[task 2026-07-01T11:25:54.576+00:00] 11:25:54 INFO - GECKO(32559) | ExceptionHandler::GenerateDump cloned child 33132
[task 2026-07-01T11:25:54.576+00:00] 11:25:54 INFO - GECKO(32559) | ExceptionHandler::SendContinueSignalToChild sent continue signal to child
[task 2026-07-01T11:25:54.577+00:00] 11:25:54 INFO - GECKO(32559) | ExceptionHandler::WaitForContinueSignal waiting for continue signal...
[task 2026-07-01T11:25:54.707+00:00] 11:25:54 INFO - GECKO(32559) | ExceptionHandler::GenerateDump minidump generation succeeded
[task 2026-07-01T11:25:54.718+00:00] 11:25:54 INFO - GECKO(32559) |
[task 2026-07-01T11:25:54.718+00:00] 11:25:54 INFO - TEST-INFO | Main app process: exit 0
[task 2026-07-01T11:25:54.718+00:00] 11:25:54 INFO - runtests.py | Application ran for: 0:01:03.438979
| Reporter | ||
Comment 1•22 days ago
|
||
Hi Sam! Could please take a look at this?
Thank you!
Comment 2•22 days ago
|
||
Observed Linux except with ThreadSanitizer enabled. Not observed for 3/3 runs on Windows. Did not run on macOS yet.
Updated•22 days ago
|
Comment 3•22 days ago
|
||
Issue surface by bug 2051353 (?) - Sam, can you fix the test or shall it be disabled where it fails?
Comment 4•22 days ago
|
||
No longer regressed by: 2050255
Is the idea that this test started failing when that patch landed? I can look into this but from the stack trace I'm not clear how I'm implicated?
Comment 5•22 days ago
|
||
:florian, since you are the author of the regressor, bug 2051353, could you take a look? Also, could you set the severity field?
For more information, please visit BugBot documentation.
Comment 6•22 days ago
|
||
Part 1 of bug 2051353 mentions:
shouldCapture() previously bailed out on the nightly channel, which meant the
mochitest-browser-screenshots jobs running on autoland and mozilla-central never
captured anything.
Is there a behavior change here?
| Comment hidden (Intermittent Failures Robot) |
Comment 8•17 days ago
|
||
Is the content of the browser/tools/mozscreenshots/ folder (which was modified by bug 2051353) really used outside of screenshot jobs?
Comment 9•14 days ago
|
||
I'm not sure if this should be testing::mozscreenshot or firefox::shell integration, but I'm pretty sure this is not related to firefox::screenshots which is the user-facing UI for capturing a screenshot. Lets try shell integration as I'm not even sure if mozscreenshot has a owner right now.
| Comment hidden (Intermittent Failures Robot) |
Comment 11•10 days ago
|
||
I've tried investigating this bug a bit. I thought I was able to reproduce it locally, but it turns out I was just seeing a different issue (bug 2054572). I tried to fix that, but it doesn't seem to help in a try run.
Looking at the log, it seems like it's timing out doing some extension initialization, maybe the Extensions folks might have an idea? The error seems to suggest that newtab is taking too long to initialize, but it looks like that should be impossible given webext-glue/background.js being like 5 lines...?
With prettified JSON from a try run I just did:
[task 2026-07-13T19:07:28.703+00:00] 19:07:28 INFO - GECKO(7271) | >>> FATAL ERROR: AsyncShutdown timeout in quit-application Conditions:
[
{
"name": "Extension startup: newtab@mozilla.org",
"state": {
"state": "Startup: Run manifest, asyncEmitManifestEntry(\"background\")"
},
"filename": "resource://gre/modules/addons/XPIProvider.sys.mjs",
"lineNumber": 2841,
"stack": [
"resource://gre/modules/addons/XPIProvider.sys.mjs:startup:2841",
"resource://gre/modules/AddonManager.sys.mjs:callProvider:282",
"resource://gre/modules/AddonManager.sys.mjs:_startProvider:589",
"resource://gre/modules/AddonManager.sys.mjs:startup:804",
"resource://gre/modules/AddonManager.sys.mjs:startup:3776",
"resource://gre/modules/amManager.sys.mjs:observe:58"
]
},
{
"name": "XPIProvider shutdown",
"state": "Awaiting startup promises",
"filename": "resource://gre/modules/addons/XPIProvider.sys.mjs",
"lineNumber": 2871,
"stack": [
"resource://gre/modules/addons/XPIProvider.sys.mjs:startup:2871",
"resource://gre/modules/AddonManager.sys.mjs:callProvider:282",
"resource://gre/modules/AddonManager.sys.mjs:_startProvider:589",
"resource://gre/modules/AddonManager.sys.mjs:startup:804",
"resource://gre/modules/AddonManager.sys.mjs:startup:3776",
"resource://gre/modules/amManager.sys.mjs:observe:58"
]
}
]
At least one completion condition failed to complete within a reasonable amount of time. Causing a crash to ensure that we do not leave the user with an unresponsive process draining resources.
Maybe if we quit too early, ...something something... this happens?
| Assignee | ||
Comment 12•9 days ago
|
||
(In reply to Duncan McIntosh [:dmcintosh] from comment #11)
Looking at the log, it seems like it's timing out doing some extension initialization, maybe the Extensions folks might have an idea? The error seems to suggest that newtab is taking too long to initialize, but it looks like that should be impossible given webext-glue/background.js being like 5 lines...?
With prettified JSON from a try run I just did:
[task 2026-07-13T19:07:28.703+00:00] 19:07:28 INFO - GECKO(7271) | >>> FATAL ERROR: AsyncShutdown timeout in quit-application Conditions: [ { "name": "Extension startup: newtab@mozilla.org", "state": { "state": "Startup: Run manifest, asyncEmitManifestEntry(\"background\")"
Looks like bug 1543354. Also possibly relevant is bug 1959339 (fixed one year ago, also a hang when screenshot is used).
This hang means that the background script is pending startup and somehow not completing. This could be due to the system being slow (and not being able to complete startup in time at shutdown), or there being a real bug that prevents the background startup from reaching completing at all (e.g. in bug 1959339 I identified an issue that prevented background load abort from being detected, causing the background startup to stall forever).
| Assignee | ||
Comment 13•9 days ago
|
||
Two parts, (1) root cause and (2) reproduction (=why does it start failing on beta).
The root cause is that createBrowserElement()'s returned Promise never settles when startup is interrupted very early.
With the repro (see below), it frequently gets stuck waiting on await this.waitInitialized in createBrowserElement, which in its turn is waiting for initWindowlessBrowser, which awaits chrome-document-global-created. When startup is aborted quickly (in this specific bug the application exit quickly if there is nothing to screenshot), that notification is never triggered, so the application hangs on the asyncshutdown blocker.
The fix here is to make sure that if we commence shutdown, that we settle/reject promises that may never get resolved:
initWindowlessBrowserat https://searchfox.org/firefox-main/rev/406555efb4216a82987a4651e1cd7aaeafa5c937/toolkit/components/extensions/ExtensionParent.sys.mjs#1464-1468await awaitFrameLoaderincreateBrowserElement
Reproduction
The log file contains the following:
>>> expected exactly one URL when using `screenshot`
The source emitting the log indicates that the screenshotting logic was skipped, that the application starts up and then immediately quits. So a minimal repro without depending on the referenced unit tests is:
profdir=$(mktemp -d)
/path/to/firefox -profile "$profdir" -screenshot http://example.com/ http://example.net/
and then checking whether the crash reporter appears, or whether stdout/stderr contains ###!!! ABORT: file resource://gre/modules/addons/XPIProvider.sys.mjs:2841
I tried reproducing with an unmodified main tree, and could not reproduce after 100 attempts, even with chaos mode.
When I looked up the latest central-as-beta sim (from today), I found https://treeherder.mozilla.org/jobs?repo=try&revision=414e308ff64e5f6fcec5fa050da561e3722cbd93&searchStr=bc&selectedTaskRun=RmS648NhRPyWOEMY90GlGg.0
... and was able to reproduce on the 2nd try. After retrying 30 times, 6 of these failed (20%), which strongly suggests that there is something special with the beta build.
And the special thing on beta is that we use different storage backends in ExtensionPermissions (JSONFile on non-Nightly, rkv on Nightly - bug 1646182), see function createStore(useRkv = AppConstants.NIGHTLY_BUILD) { in ExtensionPermissions.sys.mjs. There is a timing difference between the two - JSONFile initialization fails fast for non-existing files (new profile), but rkv can take more time (e.g. measured ~70ms vs 2ms on Linux).
We call ExtensionPermissions.get() in parseManifest, called from loadManifest, after which there is a clearCache call that may reject if shutdown has commenced, with "clearCacheForExtensionPrincipal called after shutdown was initiated" (source). The rkv vs JSONFile delay is so significant that it can enable the difference between passing and failing that checkpoint. When we reach that point quickly (e.g. on beta), we fly past the check and hit the bug I described at the top of my comment. When we reach that point slowly (on Nightly), we detect shutdown and bail out earlier.
Updated•9 days ago
|
| Assignee | ||
Comment 14•7 days ago
|
||
Prevent background startup from getting stuck due to never-settling
promises in various stages of HiddenXULWindow initialization.
Also simplify the separate "chrome-document-global-created" and
promiseDocumentLoaded observers with a single "chrome-document-loaded"
observer. Due to the sync about:blank effort, and the fact that we are
trying to load one in-process chrome document, that notification is
guaranteed to do the right thing (and is simpler).
Comment 15•6 days ago
|
||
uploaded patch to latest simulation and it fixes the initial bc issue but it's causing this xpcshell failure -> https://treeherder.mozilla.org/logviewer?job_id=579322455&repo=try&task=Sw7DMOx1QiGv_6MtMC6yxw.0
| Assignee | ||
Comment 16•6 days ago
|
||
(In reply to amarc from comment #15)
uploaded patch to latest simulation and it fixes the initial bc issue but it's causing this xpcshell failure -> https://treeherder.mozilla.org/logviewer?job_id=579322455&repo=try&task=Sw7DMOx1QiGv_6MtMC6yxw.0
I saw that in the try push I hacked together in bug 2055727 (https://treeherder.mozilla.org/jobs?repo=try&revision=971a7c16ae05ebbac9878127a95d6f5808df86a3).
It is a new unit test, and it is a debug-only assertion. It is a pre-existing issue not caused by my change, only an increase in test coverage revealing a pre-existing issue. I am therefore going to mark that new test as skipped on debug builds. There are still two other new tests that provide plenty of coverage for the scenario hit in this bug.
Comment 17•6 days ago
|
||
Comment 18•6 days ago
|
||
Comment 19•6 days ago
|
||
Reverted this because it was causing devtools failures in browser_webextension_descriptor.js.
- Revert link
- Push with failures
- Failure Log
- Failure line: TEST-UNEXPECTED-FAIL | devtools/client/framework/test/browser_webextension_descriptor.js | Shutdown - leaked window until shutdown [url = chrome://extensions/content/dummy.xhtml]
Updated•6 days ago
|
Comment 20•4 days ago
|
||
| Comment hidden (Intermittent Failures Robot) |
Comment 22•3 days ago
|
||
| bugherder | ||
| Assignee | ||
Comment 23•3 days ago
|
||
The window leak resulting in the backout above was resolved. It was due to await Promise.race([shuttingDownPromise, awaitFrameLoader]):
awaitFrameLoaderresolved to an object holding a reference to thewindow.shuttingDownPromisedid not settle at the time of the leakcheck, essentially a never-settling promise.
Any resolution value of Promise.race() is kept alive for as long as any of the other promises have not settled. That was reported before as bug 1761401.
As an alternative I changed to AbortController instead: https://phabricator.services.mozilla.com/D312620?vs=1325283&id=1325595
Comment 24•3 days ago
|
||
Verified in today's beta simulation and there is no bc or xpcshell failures.
https://treeherder.mozilla.org/jobs?repo=try&group_state=expanded&resultStatus=testfailed%2Cbusted%2Cexception%2Cretry%2Cusercancel&revision=cac6c4bc2a8bc6ed13743ba522f88d50d72750b6
Description
•