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

[task 2022-09-01T21:13:19.882Z] 21:13:19     INFO - TEST-PASS | browser/components/firefoxview/tests/browser/browser_colorways_card.js | Colorway description should be visible - 
[task 2022-09-01T21:13:19.883Z] 21:13:19     INFO - Buffered messages finished
[task 2022-09-01T21:13:19.883Z] 21:13:19     INFO - TEST-UNEXPECTED-FAIL | browser/components/firefoxview/tests/browser/browser_colorways_card.js | Colorway figure should be shown - Got "https://www.example.com/collection.avif", expected "https://www.example.com/colorway.avif"
[task 2022-09-01T21:13:19.884Z] 21:13:19     INFO - Stack trace:
[task 2022-09-01T21:13:19.885Z] 21:13:19     INFO - chrome://mochikit/content/browser-test.js:test_is:1468
[task 2022-09-01T21:13:19.885Z] 21:13:19     INFO - chrome://mochitests/content/browser/browser/components/firefoxview/tests/browser/browser_colorways_card.js:active_colorway_test/<:249
[task 2022-09-01T21:13:19.886Z] 21:13:19     INFO - resource://testing-common/BrowserTestUtils.jsm:withNewTab:151
[task 2022-09-01T21:13:19.886Z] 21:13:19     INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-09-01T21:13:19.887Z] 21:13:19     INFO - TEST-UNEXPECTED-FAIL | browser/components/firefoxview/tests/browser/browser_colorways_card.js | Colorway title should be shown - Got "Independent Voices", expected "Mock Theme"
[task 2022-09-01T21:13:19.888Z] 21:13:19     INFO - Stack trace:
[task 2022-09-01T21:13:19.888Z] 21:13:19     INFO - chrome://mochikit/content/browser-test.js:test_is:1468
[task 2022-09-01T21:13:19.889Z] 21:13:19     INFO - chrome://mochitests/content/browser/browser/components/firefoxview/tests/browser/browser_colorways_card.js:active_colorway_test/<:254
[task 2022-09-01T21:13:19.889Z] 21:13:19     INFO - resource://testing-common/BrowserTestUtils.jsm:withNewTab:151
[task 2022-09-01T21:13:19.890Z] 21:13:19     INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-09-01T21:13:19.891Z] 21:13:19     INFO - TEST-UNEXPECTED-FAIL | browser/components/firefoxview/tests/browser/browser_colorways_card.js | Colorway description should be shown - Got "colorway-collection-independent-voices-description", expected "firefoxview-colorway-description"
[task 2022-09-01T21:13:19.891Z] 21:13:19     INFO - Stack trace:
[task 2022-09-01T21:13:19.892Z] 21:13:19     INFO - chrome://mochikit/content/browser-test.js:test_is:1468
[task 2022-09-01T21:13:19.892Z] 21:13:19     INFO - chrome://mochitests/content/browser/browser/components/firefoxview/tests/browser/browser_colorways_card.js:active_colorway_test/<:262
[task 2022-09-01T21:13:19.893Z] 21:13:19     INFO - resource://testing-common/BrowserTestUtils.jsm:withNewTab:151
[task 2022-09-01T21:13:19.893Z] 21:13:19     INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-09-01T21:13:19.895Z] 21:13:19     INFO - TEST-UNEXPECTED-FAIL | browser/components/firefoxview/tests/browser/browser_colorways_card.js | Uncaught exception in test - at chrome://mochitests/content/browser/browser/components/firefoxview/tests/browser/browser_colorways_card.js:268 - TypeError: can't access property "intensity", descriptionL10nAttributes.args is null
[task 2022-09-01T21:13:19.895Z] 21:13:19     INFO - Stack trace:
[task 2022-09-01T21:13:19.896Z] 21:13:19     INFO - active_colorway_test/<@chrome://mochitests/content/browser/browser/components/firefoxview/tests/browser/browser_colorways_card.js:268:1
[task 2022-09-01T21:13:19.896Z] 21:13:19     INFO - withNewTab@resource://testing-common/BrowserTestUtils.jsm:151:24
[task 2022-09-01T21:13:19.899Z] 21:13:19     INFO - Leaving test bound active_colorway_test
[task 2022-09-01T21:13:19.900Z] 21:13:19     INFO - Entering test bound active_colorway_without_intensity_test
[task 2022-09-01T21:13:19.900Z] 21:13:19     INFO - GECKO(2006) | [Parent 2006, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x805E0006 (NS_ERROR_CONTENT_BLOCKED): file /builds/worker/checkouts/gecko/dom/security/nsContentSecurityManager.cpp:1417
[task 2022-09-01T21:13:19.901Z] 21:13:19     INFO - GECKO(2006) | [Parent 2006, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpChannel.cpp:5778
[task 2022-09-01T21:13:19.901Z] 21:13:19     INFO - GECKO(2006) | [Parent 2006: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 7f889285bc00 == 12 [pid = 2006] [id = 11]
[task 2022-09-01T21:13:19.902Z] 21:13:19     INFO - GECKO(2006) | [Parent 2006: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 29 (7f88914dde30) [pid = 2006] [serial = 29] [outer = 0]
[task 2022-09-01T21:13:19.902Z] 21:13:19     INFO - GECKO(2006) | [Parent 2006: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 30 (7f8892867800) [pid = 2006] [serial = 30] [outer = 7f88914dde30]
[task 2022-09-01T21:13:20.039Z] 21:13:20     INFO - Console message: [JavaScript Error: "Content Security Policy: The page’s settings blocked the loading of a resource at https://www.example.com/colorway.avif (“img-src”)." {file: "chrome" line: 185}]
[task 2022-09-01T21:13:20.055Z] 21:13:20     INFO - GECKO(2006) | [Parent 2006: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 31 (7f888b9a9c00) [pid = 2006] [serial = 31] [outer = 7f88914dde30]
[task 2022-09-01T21:13:20.106Z] 21:13:20     INFO - GECKO(2006) | [Parent 2006, Main Thread] WARNING: Failed to retarget HTML data delivery to the parser thread.: file /builds/worker/checkouts/gecko/parser/html/nsHtml5StreamParser.cpp:1234
[task 2022-09-01T21:13:20.337Z] 21:13:20     INFO - GECKO(2006) | [Parent 2006, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x805E0006 (NS_ERROR_CONTENT_BLOCKED): file /builds/worker/checkouts/gecko/dom/security/nsContentSecurityManager.cpp:1417
[task 2022-09-01T21:13:20.338Z] 21:13:20     INFO - GECKO(2006) | [Parent 2006, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpChannel.cpp:5778
[task 2022-09-01T21:13:20.483Z] 21:13:20     INFO - Console message: [JavaScript Error: "Content Security Policy: The page’s settings blocked the loading of a resource at https://www.example.com/colorway.avif (“img-src”)." {file: "chrome" line: 185}]

This started to fail frequently.
https://treeherder.mozilla.org/jobs?repo=autoland&group_state=expanded&collapsedPushes=842382&resultStatus=pending%2Crunning%2Csuccess%2Ctestfailed%2Cbusted%2Cexception%2Cretry%2Cusercancel&searchStr=os%2Cx%2C11%2Cwebrender%2Cshippable%2Copt%2Cmochitests%2Cwith%2Cnetworking%2Con%2Csocket%2Cprocess%2Ctest-macosx1100-64-shippable-qr%2Fopt-mochitest-browser-chrome-spi-nw%2Cbc5&fromchange=32722fb2cb537181fd5cf116f18b730448f1c1f4&selectedTaskRun=P1mUTLjBS3SjybfVpW7v9A.0&tochange=7e750a604f4ef65f0e83610f9c01ad56e89174ed

Log: https://treeherder.mozilla.org/logviewer?job_id=396803915&repo=autoland&lineNumber=3026
I assume this is a regression from https://hg.mozilla.org/integration/autoland/rev/4791730df49f40f22e496937ab5fe5dd3c50b483
Hanna, could you please take a look at this?

Looks like this test is very sad on macOS opt now.

I can't reproduce this locally, but I think I'm on the path to finding a fix. It looks like my changes for Bug 1780441 (mainly running the tests in a newly opened window + closing that window before disabling the theme) triggered the issue described in Bug 1742842 in these tests. I'm working on changes to keep using the withFirefoxView helper but have the window open/close mechanics be more similar to what they were before my patch, and possibly to add a "transitionend" listener on the nav bar as this transition seems like a possible culprit for triggering that vsync issue given that it happens when we enable/disable themes.

Might take a bit of time to verify my fix on try though.

From what I can tell switching to withFirefoxView and opening a new window to run these tests in + closing that window before disabling the theme messed with the timing of these tests in such a way that we started getting that vsync error shown in the logs. I've switched to running all these tests in the same window, which looks good from a couple of try pushes:

https://treeherder.mozilla.org/jobs?repo=try&revision=9a5f379ecc48bda08eab67210278b547f558f856

https://treeherder.mozilla.org/jobs?repo=try&revision=76b909924455fda54165ffeaa00b3654b4decd09

I'll file a follow up bug to change the default behaviour of withFirefoxView is to run tests in the same window, as this has come up before.

Also worth noting that even if this patch lands and fixes the new frequent intermittent we will likely still see the less frequent intermittents that happened prior to the change for Bug 1780441.

https://hg.mozilla.org/mozilla-central/rev/04f05185596d

This doesn't seem to have improved, unfortunately. Florian or other folks on the perf team may be able to help work out what this vsync issue is? It's quite possible there's something more fundamental going wrong that we're "just" happening to trigger in this test.

(In reply to :Gijs (he/him) from comment #19)

This doesn't seem to have improved, unfortunately. Florian or other folks on the perf team may be able to help work out what this vsync issue is? It's quite possible there's something more fundamental going wrong that we're "just" happening to trigger in this test.

Yeah the simplest change looked promising on try pushes but doesn't seem to have worked out. I'll reach out to Florian/the perf team.

This patch completes what I tried to do in D162617. Poking around at this again I realized (embarassingly) that I forgot to change one test to run in the same window, and it was the test that failed consistently on try when run in isolation.

Based on the profile Florian helped me look at it seemed like we had a window leak and were possibly still trying to run animations in a window that had been closed. It feels plausible that going back to what we were doing before my initial change - running all the tests in the same window and only closing that window once they had all finished - might still be the fix for this intermittent.

Recent try push looked good: https://treeherder.mozilla.org/jobs?repo=try&revision=3836fc6ceeb2f9c522a2d2a0126f6bdc9aea1bb6&selectedTaskRun=arwidi8RROCcJkUY-hMg1g.0

Compared to running similar jobs without this one change: https://treeherder.mozilla.org/jobs?repo=try&revision=8c2345419537e5465104edfd29c270496db90cef

https://hg.mozilla.org/mozilla-central/rev/7d1e02fd22b3

It looks like my patch that landed a few days ago at least succeeded in making this intermittent a lot less frequent. I'm not totally sure what the protocol is since this was failing intermittently even before my original change that caused it to fail in a fun new way, but I've removed the leave-open keyword that I added.

The Bugbug bot thinks this bug should belong to the 'Firefox::Firefox View' component, and is moving the bug to that component. Please correct in case you think the bot is wrong.