1356394 - browser_perf-button-states.js and browser_markers-minor-gc.js fail when Screenshots is landed as a system add-on (Legacy?)

Status: RESOLVED FIXED

(DevTools :: General, defect)

Description

[Mark Banner (:standard8)]

We're trying to land Screenshots in bug 1346825. When we do so, we're hitting failures with browser_perf-button-states.js.

The failure mode is:

GECKO(87482) | console.error:
GECKO(87482) |   Message: [Exception... "Component returned failure code: 0x8000ffff (NS_ERROR_UNEXPECTED) [nsIStringBundle.GetStringFromName]"  nsresult: "0x8000ffff (NS_ERROR_UNEXPECTED)"  location: "JS frame :: resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/system.js :: getSystemInfo :: line 77"  data: no]
GECKO(87482) |   Stack:
GECKO(87482) |     getSystemInfo@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/system.js:77:17
GECKO(87482) | _run@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/task.js:311:39
GECKO(87482) | TaskImpl@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/task.js:273:3
GECKO(87482) | asyncFunction@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/task.js:247:14
GECKO(87482) | exports.PerformanceRecorder<.startRecording<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/performance/recorder.js:376:29
GECKO(87482) | _run@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/task.js:311:39
GECKO(87482) | process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:922:23
GECKO(87482) | walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:806:7
GECKO(87482) | Promise*scheduleWalkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:739:11
GECKO(87482) | schedulePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:770:7
GECKO(87482) | Promise.prototype.then@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:455:5
GECKO(87482) | Promise.all/<@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:577:9
GECKO(87482) | Promise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:390:5
GECKO(87482) | Promise.all@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:554:10
GECKO(87482) | exports.PerformanceRecorder<.startRecording<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/performance/recorder.js:358:73
GECKO(87482) | _run@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/task.js:311:39
GECKO(87482) | TaskImpl@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/task.js:273:3
GECKO(87482) | asyncFunction@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/task.js:247:14
GECKO(87482) | PerformanceActor<.startRecording<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/actors/performance.js:76:27
GECKO(87482) | _run@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/task.js:311:39
GECKO(87482) | TaskImpl@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/task.js:273:3
GECKO(87482) | asyncFunction@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/task.js:247:14
GECKO(87482) | handler@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/protocol.js:1082:19
GECKO(87482) | onPacket@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/main.js:1759:15
GECKO(87482) | receiveMessage@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/transport/transport.js:761:7
GECKO(87482) | getSystemInfo@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/system.js:77:17
GECKO(87482) | _run@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/task.js:311:39
GECKO(87482) | TaskImpl@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/task.js:273:3
GECKO(87482) | asyncFunction@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/task.js:247:14
GECKO(87482) | exports.PerformanceRecorder<.startRecording<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/performance/recorder.js:376:29
GECKO(87482) | _run@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/task.js:311:39
GECKO(87482) | process@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:922:23
GECKO(87482) | walkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:806:7
GECKO(87482) | Promise*scheduleWalkerLoop@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:739:11
GECKO(87482) | schedulePromise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:770:7
GECKO(87482) | Promise.prototype.then@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:455:5
GECKO(87482) | Promise.all/<@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:577:9
GECKO(87482) | Promise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:390:5
GECKO(87482) | Promise.all@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:554:10
GECKO(87482) | exports.PerformanceRecorder<.startRecording<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/performance/recorder.js:358:73
GECKO(87482) | _run@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/task.js:311:39
GECKO(87482) | TaskImpl@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/task.js:273:3
GECKO(87482) | asyncFunction@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/task.js:247:14
GECKO(87482) | PerformanceActor<.startRecording<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/actors/performance.js:76:27
GECKO(87482) | _run@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/task.js:311:39
GECKO(87482) | TaskImpl@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/task.js:273:3
GECKO(87482) | asyncFunction@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/task.js:247:14
GECKO(87482) | handler@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/protocol.js:1082:19
GECKO(87482) | onPacket@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/main.js:1759:15
GECKO(87482) | receiveMessage@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/transport/transport.js:761:7
GECKO(87482) | --DOMWINDOW == 19 (0x15a0b4000) [pid = 87482] [serial = 7] [outer = 0x0] [url = about:blank]
25 INFO TEST-UNEXPECTED-FAIL | devtools/client/performance/test/browser_perf-button-states.js | A promise chain failed to handle a rejection:  - Protocol error (unknownError): Component returned failure code: 0x8000ffff (NS_ERROR_UNEXPECTED) [nsIStringBundle.GetStringFromName]
Stack trace:
JS frame :: resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js :: register :: line 199
JS frame :: resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js :: completePromise :: line 711
JS frame :: resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/task.js :: _handleException :: line 442
JS frame :: resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/task.js :: _run :: line 323
JS frame :: resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js :: process :: line 925
JS frame :: resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js :: walkerLoop :: line 806

This is failing trying to get a brand name from brand.properties.

I can reproduce this 100% on Mac with a debug build.

Comparing the good & bad the logs, it appears that when the extension is enabled, then cubeb gets initialised multiple times, and can't get the brand.properties. This seems to kick the chrome protocol handler into a mode where it thinks brand.properties doesn't exist, and won't ever load, giving the assertion when the test runs.

Comment 1

[Mark Banner (:standard8)]

I should also note: Screenshots is being landed as a legacy add-on, however the WebExtension part is currently disabled via preferences that bootstrap.js monitors.


I'm going to be out until Tuesday, so any help would be useful as we want to land this before then.

Comment 2

[Dave Townsend [:mossop]]

(In reply to Mark Banner (:standard8) from comment #0)
> We're trying to land Screenshots in bug 1346825. When we do so, we're
> hitting failures with browser_perf-button-states.js.

We also see failures in browser_markers-minor-gc.js and possibly other tests are failing too, though those might be knock-on failures.

> This is failing trying to get a brand name from brand.properties.
> 
> I can reproduce this 100% on Mac with a debug build.

I can barely reproduce on Windows, going to try OSX next.

> Comparing the good & bad the logs, it appears that when the extension is
> enabled, then cubeb gets initialised multiple times, and can't get the
> brand.properties. This seems to kick the chrome protocol handler into a mode
> where it thinks brand.properties doesn't exist, and won't ever load, giving
> the assertion when the test runs.

I don't think that this is correct. I see the cubeb error even on successful runs.

Comment 3

[Robert Helmer [:rhelmer]]

kmag tracked this down - even though bootstrap.js is waiting until it observes "sessionstore-windows-restored" to start the embedded WebExtension, because it's declared as an embedded WE in the install.rdf the manifest.json gets parsed at startup.

There is some underlying race condition here when WE manifest parsing happens at startup - however we don't need/want to do this parsing at startup so we can just make the WE not be embedded and install+start it after "sessionstore-windows-restored".

Comment 4

[Robert Helmer [:rhelmer]]

Attachment: PR to remove embedded web extension entry from install manifest

See comment 3. I'm able to reliably reproduce locally (debug artifact build on macOS) within 10 runs without this patch, and cannot reproduce with it.

To re-land, it'd probably be easiest to make a new upstream release of Screenshots, re-open the review in bug 1346825 and amend the "Export Screenshots v6.3.0" commit to include the newer release.

However that's up to you - please let me know if this resolves the failure and still works as expected.

Comment 5

[Kris Maglione [:kmag]]

It's worth noting that we don't parse manifest.json at every startup, only when it's first installed. But since mochitests use a fresh profile for every instance, every startup is treated as a fresh install.

Comment 6

[Dave Townsend [:mossop]]

Comment on attachment 8858212 [details] [review]
PR to remove embedded web extension entry from install manifest

I r+ this and I'm going to go ahead and re-land with it included.

Comment 7

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

And now for a head scratcher... Mossop relanded with the fix on mozilla-inbound. That push has NOT been merged around to m-c or autoland.

Over on autoland tonight, I see https://treeherder.mozilla.org/logviewer.html#?job_id=91794655&repo=autoland

TEST-UNEXPECTED-FAIL | devtools/client/performance/test/browser_perf-range-changed-render.js | Uncaught exception - Protocol error (unknownError): Component returned failure code: 0x8000ffff (NS_ERROR_UNEXPECTED) [nsIStringBundle.GetStringFromName] 
TEST-UNEXPECTED-FAIL | devtools/client/performance/test/browser_perf-range-changed-render.js | Found an unexpected tab at the end of test run: http://example.com/browser/devtools/client/performance/test/doc_simple-test.html#4572385522885915 - 
TEST-UNEXPECTED-FAIL | devtools/client/performance/test/browser_perf-recording-notices-03.js | Uncaught exception - Protocol error (unknownError): Component returned failure code: 0x8000ffff (NS_ERROR_UNEXPECTED) [nsIStringBundle.GetStringFromName] 
TEST-UNEXPECTED-FAIL | devtools/client/performance/test/browser_perf-recording-notices-03.js | Found an unexpected tab at the end of test run: http://example.com/browser/devtools/client/performance/test/doc_simple-test.html#1692939382845701 - 
TEST-UNEXPECTED-FAIL | devtools/client/performance/test/browser_perf-recording-notices-04.js | Uncaught exception - Protocol error (unknownError): Component returned failure code: 0x8000ffff (NS_ERROR_UNEXPECTED) [nsIStringBundle.GetStringFromName] 
TEST-UNEXPECTED-FAIL | devtools/client/performance/test/browser_perf-recording-notices-04.js | Found an unexpected tab at the end of test run: http://example.com/browser/devtools/client/performance/test/doc_simple-test.html#613005313262344 -

Comment 8

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

I guess maybe the fix will fix this when it merges over to autoland, too?

Comment 9

[Kris Maglione [:kmag]]

No, the only change was to the add-on itself.

The errors from Cubeb trying to get the same property from the branding bundle have been showing up in builds without the extension, too, so this issue clearly exists on its own. The add-on installation apparently just made whatever race is involved more likely.

Comment 10

[Mark Banner (:standard8)]

This has landed, so I think I'll mark this as fixed. There could be further Cubeb issues here, but its hard to tell.