Closed Bug 2013575 Opened 2 months ago Closed 1 month ago

Intermittent browser/components/firefoxview/tests/browser/browser_chats_firefoxview.js | test_chat_with_url_opens_sidebar - Test timed out

Categories

(Firefox :: Firefox View, defect, P5)

defect

Tracking

()

RESOLVED WONTFIX
Tracking Status
firefox-esr140 --- unaffected
firefox147 --- unaffected
firefox148 --- unaffected
firefox149 --- affected

People

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

References

(Blocks 1 open bug)

Details

(Keywords: intermittent-failure, regression, test-verify-fail, Whiteboard: [genai][chat])

Attachments

(1 obsolete file)

Filed by: abutkovits [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=546317411&repo=autoland&task=TOasjaHySyiptJ8_enTDAQ.0
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/TOasjaHySyiptJ8_enTDAQ/runs/0/artifacts/public/logs/live_backing.log
Reftest URL: https://hg.mozilla.org/mozilla-central/raw-file/default/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/TOasjaHySyiptJ8_enTDAQ/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1


[task 2026-01-30T15:51:16.808+00:00] 15:51:16     INFO - TEST-PASS | browser/components/firefoxview/tests/browser/browser_chats_firefoxview.js | test_chat_with_url_opens_sidebar - Chat should have the correct URL - "https://example.com/" == "https://example.com/"
[task 2026-01-30T15:51:16.809+00:00] 15:51:16     INFO - Console message: [JavaScript Warning: "Layout was forced before the page was fully loaded. If stylesheets are not yet loaded this may cause a flash of unstyled content." {file: "chrome://browser/content/aiwindow/aiWindow.html" line: 0}]
[task 2026-01-30T15:51:16.809+00:00] 15:51:16     INFO - Buffered messages logged at 15:48:23
[task 2026-01-30T15:51:16.810+00:00] 15:51:16     INFO - Console message: [JavaScript Warning: "Sending message that cannot be cloned. Are you trying to send an XPCOM object?" {file: "moz-src:///browser/components/aiwindow/ui/actors/AIChatContentParent.sys.mjs" line: 16}]
[task 2026-01-30T15:51:16.811+00:00] 15:51:16     INFO - Console message: [JavaScript Warning: "[fluent] Missing message in locale en-US: aiwindow-copy-message" {file: "about:aichatcontent" line: 0}]
[task 2026-01-30T15:51:16.812+00:00] 15:51:16     INFO - Console message: [JavaScript Warning: "[fluent] Missing message in locale en-US: aiwindow-retry" {file: "about:aichatcontent" line: 0}]
[task 2026-01-30T15:51:16.813+00:00] 15:51:16     INFO - Console message: [JavaScript Warning: "[fluent] Couldn't find a message: aiwindow-copy-message" {file: "about:aichatcontent" line: 0}]
[task 2026-01-30T15:51:16.813+00:00] 15:51:16     INFO - Console message: [JavaScript Warning: "[fluent] Couldn't find a message: aiwindow-retry" {file: "about:aichatcontent" line: 0}]
[task 2026-01-30T15:51:16.814+00:00] 15:51:16     INFO - Console message: [JavaScript Warning: "[fluent] Missing message in locale en-US: aiwindow-copy-message" {file: "about:aichatcontent" line: 0}]
[task 2026-01-30T15:51:16.815+00:00] 15:51:16     INFO - Console message: [JavaScript Warning: "[fluent] Missing message in locale en-US: aiwindow-retry" {file: "about:aichatcontent" line: 0}]
[task 2026-01-30T15:51:16.816+00:00] 15:51:16     INFO - Console message: [JavaScript Warning: "[fluent] Couldn't find a message: aiwindow-copy-message" {file: "about:aichatcontent" line: 0}]
[task 2026-01-30T15:51:16.816+00:00] 15:51:16     INFO - Console message: [JavaScript Warning: "[fluent] Couldn't find a message: aiwindow-retry" {file: "about:aichatcontent" line: 0}]
[task 2026-01-30T15:51:16.817+00:00] 15:51:16     INFO - Console message: [JavaScript Warning: "[dom/l10n] Errors during l10n mutation frame." {file: "about:aichatcontent" line: 0}]
[task 2026-01-30T15:51:16.818+00:00] 15:51:16     INFO - Console message: [JavaScript Error: "InvalidStateError: [fluent] Missing message in locale en-US: aiwindow-copy-message"]
[task 2026-01-30T15:51:16.819+00:00] 15:51:16     INFO - Console message: [JavaScript Warning: "[fluent] Missing message in locale en-US: aiwindow-copy-message" {file: "about:aichatcontent" line: 0}]
[task 2026-01-30T15:51:16.819+00:00] 15:51:16     INFO - Console message: [JavaScript Warning: "[fluent] Couldn't find a message: aiwindow-copy-message" {file: "about:aichatcontent" line: 0}]
[task 2026-01-30T15:51:16.820+00:00] 15:51:16     INFO - Console message: [JavaScript Warning: "[fluent] Missing message in locale en-US: aiwindow-retry" {file: "about:aichatcontent" line: 0}]
[task 2026-01-30T15:51:16.821+00:00] 15:51:16     INFO - Console message: [JavaScript Warning: "[fluent] Couldn't find a message: aiwindow-retry" {file: "about:aichatcontent" line: 0}]
[task 2026-01-30T15:51:16.822+00:00] 15:51:16     INFO - Console message: [JavaScript Error: "InvalidStateError: [fluent] Missing message in locale en-US: aiwindow-copy-message"]
[task 2026-01-30T15:51:16.822+00:00] 15:51:16     INFO - Console message: [JavaScript Error: "InvalidStateError: [fluent] Missing message in locale en-US: aiwindow-retry"]
[task 2026-01-30T15:51:16.823+00:00] 15:51:16     INFO - Buffered messages logged at 15:49:45
[task 2026-01-30T15:51:16.824+00:00] 15:51:16     INFO - Longer timeout required, waiting longer...  Remaining timeouts: 1
[task 2026-01-30T15:51:16.824+00:00] 15:51:16     INFO - Buffered messages finished
[task 2026-01-30T15:51:16.825+00:00] 15:51:16     INFO - TEST-UNEXPECTED-FAIL | browser/components/firefoxview/tests/browser/browser_chats_firefoxview.js | test_chat_with_url_opens_sidebar - Test timed out
[task 2026-01-30T15:51:16.825+00:00] 15:51:16     INFO - TEST-UNEXPECTED-TIMEOUT | browser/components/firefoxview/tests/browser/browser_chats_firefoxview.js | Test timed out
[task 2026-01-30T15:51:16.825+00:00] 15:51:16     INFO - TEST-INFO took 180554ms
[task 2026-01-30T15:51:16.826+00:00] 15:51:16     INFO - GECKO(7841) | Completed ShutdownLeaks collections in process 7841
[task 2026-01-30T15:51:16.826+00:00] 15:51:16     INFO - TEST-START | Shutdown
[task 2026-01-30T15:51:16.826+00:00] 15:51:16     INFO - Browser Chrome Test Summary
[task 2026-01-30T15:51:16.827+00:00] 15:51:16     INFO - Passed:  151
[task 2026-01-30T15:51:16.827+00:00] 15:51:16     INFO - Failed:  1
[task 2026-01-30T15:51:16.828+00:00] 15:51:16     INFO - Todo:    0
[task 2026-01-30T15:51:16.828+00:00] 15:51:16     INFO - Mode:    e10s
[task 2026-01-30T15:51:16.829+00:00] 15:51:16     INFO - *** End BrowserChrome Test Results ***
[task 2026-01-30T15:51:16.829+00:00] 15:51:16     INFO - GECKO(7841) | 1769788275980	Marionette	TRACE	Received observer notification quit-application
[task 2026-01-30T15:51:16.830+00:00] 15:51:16     INFO - GECKO(7841) | 1769788275980	Marionette	TRACE	Application is shutting down with reason: "shutdown"
[task 2026-01-30T15:51:16.830+00:00] 15:51:16     INFO - GECKO(7841) | 1769788275980	Marionette	INFO	Stopped listening on port 2828
[task 2026-01-30T15:51:16.831+00:00] 15:51:16     INFO - GECKO(7841) | [Child 7960: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 7f4c20629800 == 5 [pid = 7960] [id = 5] [url = moz-extension://9a310967-e580-48bf-b3e8-4eafebbc122d/_generated_background_page.html]
[task 2026-01-30T15:51:16.831+00:00] 15:51:16     INFO - GECKO(7841) | [Child 7960: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 7f4c20626400 == 4 [pid = 7960] [id = 4] [url = moz-extension://ff30cea7-d812-46af-b120-bd8151d1d71a/_generated_background_page.html]
[task 2026-01-30T15:51:16.832+00:00] 15:51:16     INFO - GECKO(7841) | [Child 7960: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 7f4c20626800 == 3 [pid = 7960] [id = 0] [url = moz-extension://1e92981a-98da-46b6-b8bb-a79d069d9854/_generated_background_page.html]
[task 2026-01-30T15:51:16.833+00:00] 15:51:16     INFO - GECKO(7841) | [Child 7960: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 7f4c2062d800 == 2 [pid = 7960] [id = 3] [url = moz-extension://b62b9929-61c8-4ca7-b659-e15fee0e6af3/_generated_background_page.html]
[task 2026-01-30T15:51:16.833+00:00] 15:51:16     INFO - GECKO(7841) | [Child 7960: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 7f4c20628c00 == 1 [pid = 7960] [id = 2] [url = moz-extension://be85addc-d523-4a8d-b67b-a02fe49b0a2c/_generated_background_page.html]
[task 2026-01-30T15:51:16.834+00:00] 15:51:16     INFO - GECKO(7841) | [Child 7960: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 7f4c20627400 == 0 [pid = 7960] [id = 1] [url = moz-extension://6fac3340-9c9e-4f6d-a0bf-c6708e2e08d0/_generated_background_page.html]
[task 2026-01-30T15:51:16.834+00:00] 15:51:16     INFO - Not taking screenshot here: see the one that was previously logged
[task 2026-01-30T15:51:16.836+00:00] 15:51:16     INFO - TEST-UNEXPECTED-FAIL | browser/components/firefoxview/tests/browser/browser_chats_firefoxview.js | test_chat_with_url_opens_sidebar - Uncaught exception received from previously timed out test test_chat_with_url_opens_sidebar - Error: The window unloaded while we were waiting for the browser to load - this should never happen.
[task 2026-01-30T15:51:16.836+00:00] 15:51:16     INFO - listener@resource://testing-common/BrowserTestUtils.sys.mjs:544:15
[task 2026-01-30T15:51:16.836+00:00] 15:51:16     INFO - EventListener.handleEvent*browserLoaded/<@resource://testing-common/BrowserTestUtils.sys.mjs:559:27
[task 2026-01-30T15:51:16.836+00:00] 15:51:16     INFO - browserLoaded@resource://testing-common/BrowserTestUtils.sys.mjs:509:12
[task 2026-01-30T15:51:16.836+00:00] 15:51:16     INFO - test_chat_with_url_opens_sidebar/<@chrome://mochitests/content/browser/browser/components/firefoxview/tests/browser/browser_chats_firefoxview.js:385:28
[task 2026-01-30T15:51:16.836+00:00] 15:51:16     INFO - async*withFirefoxView@resource://testing-common/FirefoxViewTestUtils.sys.mjs:158:22
[task 2026-01-30T15:51:16.836+00:00] 15:51:16     INFO - async*test_chat_with_url_opens_sidebar@chrome://mochitests/content/browser/browser/components/firefoxview/tests/browser/browser_chats_firefoxview.js:355:9
[task 2026-01-30T15:51:16.836+00:00] 15:51:16     INFO - async*handleTask@chrome://mochikit/content/browser-test.js:1302:26
[task 2026-01-30T15:51:16.836+00:00] 15:51:16     INFO - _runTaskBasedTest@chrome://mochikit/content/browser-test.js:1392:18
[task 2026-01-30T15:51:16.836+00:00] 15:51:16     INFO - async*Tester_execTest@chrome://mochikit/content/browser-test.js:1539:14
[task 2026-01-30T15:51:16.836+00:00] 15:51:16     INFO - nextTest/<@chrome://mochikit/content/browser-test.js:1276:14
[task 2026-01-30T15:51:16.836+00:00] 15:51:16     INFO - SimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1063:13
[task 2026-01-30T15:51:16.837+00:00] 15:51:16     INFO - Entering test test_delete_chat
[task 2026-01-30T15:51:16.838+00:00] 15:51:16     INFO - GECKO(7841) | 1769788276142	Marionette	DEBUG	Marionette stopped listening
[task 2026-01-30T15:51:16.838+00:00] 15:51:16     INFO - GECKO(7841) | [Child 8000: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 7f4c20646800 == 0 [pid = 8000] [id = 3] [url = about:aichatcontent]
[task 2026-01-30T15:51:16.839+00:00] 15:51:16     INFO - GECKO(7841) | [Parent 7841: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 7f1c654c3800 == 11 [pid = 7841] [id = 42] [url = about:aichatcontent]
[task 2026-01-30T15:51:16.839+00:00] 15:51:16     INFO - GECKO(7841) | [Parent 7841: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 7f1c75920c00 == 10 [pid = 7841] [id = 37] [url = about:blank]
[task 2026-01-30T15:51:16.840+00:00] 15:51:16     INFO - GECKO(7841) | [Parent 7841: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 7f1c6be22c00 == 9 [pid = 7841] [id = 39] [url = about:aichatcontent]
[task 2026-01-30T15:51:16.840+00:00] 15:51:16     INFO - GECKO(7841) | [Parent 7841: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 7f1c8e107800 == 8 [pid = 7841] [id = 1] [url = chrome://extensions/content/dummy.xhtml]
[task 2026-01-30T15:51:16.841+00:00] 15:51:16     INFO - GECKO(7841) | [Parent 7841, Socket Thread] WARNING: cannot post event if not initialized: file /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpConnectionMgr.cpp:233
[task 2026-01-30T15:51:16.842+00:00] 15:51:16     INFO - GECKO(7841) | [Parent 7841, Socket Thread] WARNING: cannot post event if not initialized: file /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpConnectionMgr.cpp:233
[task 2026-01-30T15:51:16.842+00:00] 15:51:16     INFO - GECKO(7841) | [Parent 7841, Socket Thread] WARNING: cannot post event if not initialized: file /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpConnectionMgr.cpp:233
[task 2026-01-30T15:51:16.843+00:00] 15:51:16     INFO - GECKO(7841) | [Child 8057: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 7f4c1fc0a400 == 0 [pid = 8057] [id = 2] [url = about:blank]
[task 2026-01-30T15:51:16.843+00:00] 15:51:16     INFO - GECKO(7841) | [Child 8215: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 7f4c20652800 == 0 [pid = 8215] [id = 0] [url = https://example.com/]
[task 2026-01-30T15:51:16.844+00:00] 15:51:16     INFO - GECKO(7841) | [Child 8057: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 1 (7f4c20687b00) [pid = 8057] [serial = 6] [outer = 0] [url = about:blank]
[task 2026-01-30T15:51:16.845+00:00] 15:51:16     INFO - GECKO(7841) | [Child 8057: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 0 (7f4c40cad600) [pid = 8057] [serial = 7] [outer = 0] [url = about:blank]
[task 2026-01-30T15:51:16.845+00:00] 15:51:16     INFO - GECKO(7841) | [Child 8215: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 1 (7f4c2066a100) [pid = 8215] [serial = 1] [outer = 0] [url = https://example.com/]
[task 2026-01-30T15:51:16.846+00:00] 15:51:16     INFO - GECKO(7841) | [Child 8215: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 0 (7f4c1fc4b400) [pid = 8215] [serial = 3] [outer = 0] [url = https://example.com/]
[task 2026-01-30T15:51:16.847+00:00] 15:51:16     INFO - GECKO(7841) | [Child 8000: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 1 (7f4c1fc36300) [pid = 8000] [serial = 10] [outer = 0] [url = about:aichatcontent]
[task 2026-01-30T15:51:16.847+00:00] 15:51:16     INFO - GECKO(7841) | [Child 8126: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 7f4c2064a800 == 0 [pid = 8126] [id = 0] [url = about:newtab]

Summary: Intermittent TV browser/components/firefoxview/tests/browser/browser_chats_firefoxview.js | test_chat_with_url_opens_sidebar - Test timed out → Intermitten browser/components/firefoxview/tests/browser/browser_chats_firefoxview.js | test_chat_with_url_opens_sidebar - Test timed out
Summary: Intermitten browser/components/firefoxview/tests/browser/browser_chats_firefoxview.js | test_chat_with_url_opens_sidebar - Test timed out → Intermittent browser/components/firefoxview/tests/browser/browser_chats_firefoxview.js | test_chat_with_url_opens_sidebar - Test timed out
Keywords: regression
Regressed by: 2010128

Set release status flags based on info from the regressing bug 2010128

:Gijs, since you are the author of the regressor, bug 2010128, could you take a look?

For more information, please visit BugBot documentation.

Flags: needinfo?(gijskruitbosch+bugs)

The first instance of this was before bug 2010128 landed and all bug 2010128 did was rename some prefs (and I checked, the prefs used by this test are correctly named), so I don't think the regression window is correct.

Honestly I think this test has been flaky since it landed in bug 2001496.

From a look at the log and the test, I suspect the issue is here:

https://searchfox.org/firefox-main/rev/5020c06022c014e5e68fa57d8f54626e7b2689ff/browser/components/firefoxview/tests/browser/browser_chats_firefoxview.js#378-385,387-391

const tabOpenedPromise = BrowserTestUtils.waitForNewTab(
  tabBrowser,
  TEST_URL1
);
EventUtils.synthesizeMouseAtCenter(mainEl, {}, browser.contentWindow);

const newTab = await tabOpenedPromise;
await BrowserTestUtils.browserLoaded(newTab.linkedBrowser);
...
// Verify the new tab loaded the URL
Assert.ok(
  newTab.linkedBrowser.currentURI.spec.includes("example.com"),
  "New tab should load the page URL"
);

Note that the waitForNewTab does not itself wait for the tab to load, but there is a separate browserLoaded() check afterwards. That is racy - if the tab has already loaded by the time we hit the await BrowserTestUtils.browserLoaded check, the browserLoaded promise (which depends on the load event firing for that tab, not on whether there is already the relevant page loaded in the tab!) will not resolve.

Looking at the log, https://treeherder.mozilla.org/logviewer?job_id=548683423&repo=autoland&lineNumber=3910-3918 , the test logs for the earlier assert ("Chat should have the correct URL") but not the next one. Also note from the timestamps for the buffered messages (logged at 16:25:11, vs the timeout at 16:28) that the test then sat there for 3 minutes, while the screenshot for the test failure shows that the test has finished loading.

I need to go to sleep and I'm out on PTO next week.

Maile, could you take a look and fix up the test? I think all that needs to happen is passing true for the waitForLoad arg in the waitForNewTab call, instead of the separate await BTU.browserLoaded() call afterwards. I also suspect the requestLongerTimeout(2) is unnecessary.

Flags: needinfo?(gijskruitbosch+bugs) → needinfo?(mlucks)
No longer regressed by: 2010128
Assignee: nobody → mlucks
Flags: needinfo?(mlucks)
Blocks: 1988017
Depends on: 2001496
Whiteboard: [genai][chat]
Attachment #9546198 - Attachment description: WIP: Bug 2013575 - resolve intermittent timing issue on browser_chats_firefoxview → Bug 2013575 - resolve intermittent timing issue on browser_chats_firefoxview

This bug is now being addressed on bug 2015921, phab D282980

Status: NEW → RESOLVED
Closed: 1 month ago
Resolution: --- → WONTFIX
Attachment #9546198 - Attachment is obsolete: true
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: