Closed Bug 1832912 Opened 1 year ago Closed 4 months ago

Intermittent browser/components/urlbar/tests/quicksuggest/browser/browser_weather.js | single tracking bug

Categories

(Firefox :: Address Bar, defect, P3)

defect

Tracking

()

RESOLVED FIXED
125 Branch
Tracking Status
firefox-esr115 --- wontfix
firefox123 --- wontfix
firefox124 --- wontfix
firefox125 --- fixed

People

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

References

(Regression)

Details

(Keywords: intermittent-failure, intermittent-testcase, regression, Whiteboard: [stockwell disable-recommended][sng])

Attachments

(1 file)

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


[task 2023-05-12T22:57:10.650Z] 22:57:10     INFO - TEST-PASS | browser/components/urlbar/tests/quicksuggest/browser/browser_weather.js | The view should remain open clicking the command - true == true - 
[task 2023-05-12T22:57:10.650Z] 22:57:10     INFO - TEST-PASS | browser/components/urlbar/tests/quicksuggest/browser/browser_weather.js | Row should have feedback acknowledgment after clicking command - true == true - 
[task 2023-05-12T22:57:10.651Z] 22:57:10     INFO - Doing dismissal
[task 2023-05-12T22:57:10.652Z] 22:57:10     INFO - TEST-PASS | browser/components/urlbar/tests/quicksuggest/browser/browser_weather.js | Weather suggestion should be present - "Weather" == "Weather" - 
[task 2023-05-12T22:57:10.652Z] 22:57:10     INFO - TEST-PASS | browser/components/urlbar/tests/quicksuggest/browser/browser_weather.js | view should be open - true == true - 
[task 2023-05-12T22:57:10.653Z] 22:57:10     INFO - TEST-PASS | browser/components/urlbar/tests/quicksuggest/browser/browser_weather.js | found the menu button at result index 1 - {"elementIndex":2} == true - 
[task 2023-05-12T22:57:10.653Z] 22:57:10     INFO - selecting the result at index 1
[task 2023-05-12T22:57:10.654Z] 22:57:10     INFO - waiting for the menu popup to open via mouse
[task 2023-05-12T22:57:10.655Z] 22:57:10     INFO - TEST-PASS | browser/components/urlbar/tests/quicksuggest/browser/browser_weather.js | Checking popup state - "open" == "open" - 
[task 2023-05-12T22:57:10.655Z] 22:57:10     INFO - Clicking menu item with selector: [data-l10n-id=firefox-suggest-weather-command-dont-show-this]
[task 2023-05-12T22:57:10.656Z] 22:57:10     INFO - Waiting for submenu popupshown event
[task 2023-05-12T22:57:10.656Z] 22:57:10     INFO - Buffered messages finished
[task 2023-05-12T22:57:10.657Z] 22:57:10     INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/quicksuggest/browser/browser_weather.js | Test timed out - 
[task 2023-05-12T22:57:10.657Z] 22:57:10     INFO - MerinoTestUtils cleanup function
[task 2023-05-12T22:57:10.658Z] 22:57:10     INFO - MerinoTestUtils uninit: Depth is now 0
[task 2023-05-12T22:57:10.658Z] 22:57:10     INFO - MerinoTestUtils uninit: Now uninitializing
[task 2023-05-12T22:57:10.659Z] 22:57:10     INFO - MockMerinoServer uninit
[task 2023-05-12T22:57:10.660Z] 22:57:10     INFO - Not taking screenshot here: see the one that was previously logged
[task 2023-05-12T22:57:10.660Z] 22:57:10     INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/quicksuggest/browser/browser_weather.js | Uncaught exception received from previously timed out test bound showLessFrequentlyAndDismissal - popupshown listener not removed before the end of test
[task 2023-05-12T22:57:10.704Z] 22:57:10     INFO - GECKO(12719) | MEMORY STAT | vsize 3394MB | residentFast 393MB | heapAllocated 203MB
[task 2023-05-12T22:57:10.705Z] 22:57:10     INFO - TEST-OK | browser/components/urlbar/tests/quicksuggest/browser/browser_weather.js | took 46727ms
[task 2023-05-12T22:57:10.725Z] 22:57:10     INFO - checking window state
[task 2023-05-12T22:57:10.753Z] 22:57:10     INFO - GECKO(12719) | Completed ShutdownLeaks collections in process 12719
[task 2023-05-12T22:57:10.753Z] 22:57:10     INFO - TEST-START | Shutdown
[task 2023-05-12T22:57:10.753Z] 22:57:10     INFO - Browser Chrome Test Summary
[task 2023-05-12T22:57:10.753Z] 22:57:10     INFO - Passed:  5774
[task 2023-05-12T22:57:10.753Z] 22:57:10     INFO - Failed:  2
[task 2023-05-12T22:57:10.753Z] 22:57:10     INFO - Todo:    5
[task 2023-05-12T22:57:10.754Z] 22:57:10     INFO - Mode:    e10s
[task 2023-05-12T22:57:10.754Z] 22:57:10     INFO - *** End BrowserChrome Test Results ***
Status: NEW → RESOLVED
Closed: 11 months ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 11 months ago9 months ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 9 months ago5 months ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

Update:
There have been 58 failures within the last 7 days:
• 3 failures on Linux 18.04 x64 WebRender debug
• 16 failures on Linux 18.04 x64 WebRender opt
• 10 failures on Linux 18.04 x64 WebRender Shippable opt
• 1 failures on Linux 18.04 x64 WebRender tsan opt
• 2 failures on OS X 10.15 WebRender opt
• 6 failures on Windows 11 x86 22H2 WebRender opt
• 3 failures on Windows 11 x86 22H2 WebRender Shippable opt
• 3 failures on Windows 11 x64 22H2 asan WebRender opt
• 1 failures on Windows 11 x64 22H2 CCov WebRender opt
• 4 failures on Windows 11 x64 22H2 WebRender debug
• 5 failures on Windows 11 x64 22H2 WebRender opt
• 4 failures on Windows 11 x64 22H2 WebRender Shippable opt
All the failures here have this failure line: TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/quicksuggest/browser/browser_weather.js | "" == "Mostly cloudy" - {"filename":"chrome://mochitests/content/browser/browser/components/urlbar/tests/quicksuggest/browser/browser_weather.js","name":"simpleUI","sourceId":880,"lineNumber":467,"columnNumber":12,"sourceLine":"","asyncCause":null,"asyncCaller":{"filename":"chrome://mochitests/content/browser/browser/components/urlbar/tests/quicksuggest/browser/head.js","name":"newTaskFn","sourceId":877,"lineNumber":668,"columnNumber":20,"sourceLine":"","asyncCause":null,"asyncCaller":{"filename":"chrome://mochikit/content/browser-test.js","name":"handleTask","sourceId":576,"lineNumber":1139,"columnNumber":26,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"_runTaskBasedTest","sourceId":576,"lineNumber":1211,"columnNumber":18,"sourceLine":"","asyncCause":null,"asyncCaller":<...>
Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=449328298&repo=mozilla-central&lineNumber=6346

[task 2024-03-04T00:15:08.855Z] 00:15:08     INFO - TEST-PASS | browser/components/urlbar/tests/quicksuggest/browser/browser_weather.js | Result telemetry type should be 'weather' - "weather" == "weather" - 
[task 2024-03-04T00:15:08.856Z] 00:15:08     INFO - Buffered messages finished
[task 2024-03-04T00:15:08.862Z] 00:15:08     INFO - TEST-UNEXPECTED-FAIL | browser/components/urlbar/tests/quicksuggest/browser/browser_weather.js | "" == "Mostly cloudy" - {"filename":"chrome://mochitests/content/browser/browser/components/urlbar/tests/quicksuggest/browser/browser_weather.js","name":"simpleUI","sourceId":880,"lineNumber":467,"columnNumber":12,"sourceLine":"","asyncCause":null,"asyncCaller":{"filename":"chrome://mochitests/content/browser/browser/components/urlbar/tests/quicksuggest/browser/head.js","name":"newTaskFn","sourceId":877,"lineNumber":668,"columnNumber":20,"sourceLine":"","asyncCause":null,"asyncCaller":{"filename":"chrome://mochikit/content/browser-test.js","name":"handleTask","sourceId":576,"lineNumber":1139,"columnNumber":26,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"_runTaskBasedTest","sourceId":576,"lineNumber":1211,"columnNumber":18,"sourceLine":"","asyncCause":null,"asyncCaller":{"filename":"chrome://mochikit/content/browser-test.js","name":"Tester_execTest","sourceId":576,"lineNumber":1353,"columnNumber":14,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/browser-test.js","name":"nextTest/<","sourceId":576,"lineNumber":1128,"columnNumber":14,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":{"filename":"chrome://mochikit/content/tests/SimpleTest/SimpleTest.js","name":"SimpleTest.waitForFocus/<","sourceId":601,"lineNumber":1058,"columnNumber":13,"sourceLine":"","asyncCause":null,"asyncCaller":null,"caller":null,"formattedStack":"SimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"formattedStack":"nextTest/<@chrome://mochikit/content/browser-test.js:1128:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"formattedStack":"async*Tester_execTest@chrome://mochikit/content/browser-test.js:1353:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1128:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"caller":null,"formattedStack":"_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1211:18\nasync*Tester_execTest@chrome://mochikit/content/browser-test.js:1353:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1128:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"formattedStack":"async*handleTask@chrome://mochikit/content/browser-test.js:1139:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1211:18\nasync*Tester_execTest@chrome://mochikit/content/browser-test.js:1353:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1128:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"caller":null,"formattedStack":"async*newTaskFn@chrome://mochitests/content/browser/browser/components/urlbar/tests/quicksuggest/browser/head.js:668:20\nasync*handleTask@chrome://mochikit/content/browser-test.js:1139:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1211:18\nasync*Tester_execTest@chrome://mochikit/content/browser-test.js:1353:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1128:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}},"caller":null,"formattedStack":"simpleUI@chrome://mochitests/content/browser/browser/components/urlbar/tests/quicksuggest/browser/browser_weather.js:467:12\nasync*newTaskFn@chrome://mochitests/content/browser/browser/components/urlbar/tests/quicksuggest/browser/head.js:668:20\nasync*handleTask@chrome://mochikit/content/browser-test.js:1139:26\n_runTaskBasedTest@chrome://mochikit/content/browser-test.js:1211:18\nasync*Tester_execTest@chrome://mochikit/content/browser-test.js:1353:14\nnextTest/<@chrome://mochikit/content/browser-test.js:1128:14\nSimpleTest.waitForFocus/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:1058:13\n","nativeSavedFrame":{}}
[task 2024-03-04T00:15:08.862Z] 00:15:08     INFO - Stack trace:
[task 2024-03-04T00:15:08.862Z] 00:15:08     INFO - chrome://mochitests/content/browser/browser/components/urlbar/tests/quicksuggest/browser/browser_weather.js:simpleUI:467
[task 2024-03-04T00:15:08.862Z] 00:15:08     INFO - chrome://mochitests/content/browser/browser/components/urlbar/tests/quicksuggest/browser/head.js:newTaskFn:668
[task 2024-03-04T00:15:08.862Z] 00:15:08     INFO - chrome://mochikit/content/browser-test.js:handleTask:1139
[task 2024-03-04T00:15:08.862Z] 00:15:08     INFO - chrome://mochikit/content/browser-test.js:_runTaskBasedTest:1211
[task 2024-03-04T00:15:08.862Z] 00:15:08     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1353
[task 2024-03-04T00:15:08.862Z] 00:15:08     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:1128
[task 2024-03-04T00:15:08.862Z] 00:15:08     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/<:1058
[task 2024-03-04T00:15:08.863Z] 00:15:08     INFO - Closing the view directly
[task 2024-03-04T00:15:08.863Z] 00:15:08     INFO - Waiting for the view to close
[task 2024-03-04T00:15:08.864Z] 00:15:08     INFO - Urlbar view closed
[task 2024-03-04T00:15:08.864Z] 00:15:08     INFO - initNimbusFeature awaiting ExperimentManager.onStartup
[task 2024-03-04T00:15:08.865Z] 00:15:08     INFO - initNimbusFeature awaiting ExperimentAPI.ready
[task 2024-03-04T00:15:08.866Z] 00:15:08     INFO - initNimbusFeature awaiting ExperimentFakes.enrollWithRollout
[task 2024-03-04T00:15:08.866Z] 00:15:08     INFO - initNimbusFeature done
[task 2024-03-04T00:15:08.867Z] 00:15:08     INFO - Waiting for the urlbar view to open
[task 2024-03-04T00:15:08.867Z] 00:15:08     INFO - Urlbar view opened
[task 2024-03-04T00:15:08.868Z] 00:15:08     INFO - TEST-PASS | browser/components/urlbar/tests/quicksuggest/browser/browser_weather.js | Result should be from a weather provider - "UrlbarProviderQuickSuggest" == "UrlbarProviderQuickSuggest" - 
Whiteboard: [stockwell needswork:owner]

Hi Drew! Can you please take a look at this? Maybe you can help us assign this to someone.
Thank you!

Flags: needinfo?(adw)

I'll take a look.

Assignee: nobody → adw
Status: REOPENED → ASSIGNED
Flags: needinfo?(adw)

bumping up priority as it's quite frequent (top 5 last week)

Priority: P5 → P3

It looks like the recent failures are with the new simple UI, which was added in bug 1882220, so I'll mark that as regressing. However, less frequent failures in this test go way back before that, so there are multiple causes here.

Keywords: regression
Regressed by: 1882220

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

I found several problems:

Problem 1:

getViewUpdate() is allowed to be async and UrlbarView awaits it even though
the Weather implementation is not async. That means the summary text content
will be updated asyncly, so browser_weather.js needs to wait for it.

This is the cause of the recent frequent failures.

Problem 2:

This has to do with add_tasks_with_rust(). When it disables the Rust backend
and forces sync, the JS backend will sync Weather with remote settings. Since
keywords are present in remote settings at that point, Weather will then start
fetching. Each task that uses add_tasks_with_rust() needs to wait for this
fetch to finish. Otherwise weather.suggestion may be null. To fix this, I
added a way for tests to register a setup function that will run each time
add_tasks_with_rust() calls an original task.

This is the cause of infrequent failures that go back to at least when Rust was
enabled by default. I think this might be the cause of recent failures in
test_weather.js and test_weather_keywords.js too so I did the same thing
there.

Problem 3:

browser_weather.js sometimes times out in verify mode, so I requested a longer
timeout. It looks like the test finishes, it just takes a long time sometimes.

Problem 4:

test_weather_keywords.js sometimes times out in verify mode. This test takes
forever to run, especially now that it uses add_tasks_with_rust(). There's no
way to request a longer timeout for xpcshell tests (?), so I added a skip-if
for verify mode. It's fine to skip verify mode for this test. Once we remove the
JS backend, we can probably remove the skip-if. If it still times out, we
could split it up.

(In reply to Drew Willcoxon :adw from comment #43)

There's no way to request a longer timeout for xpcshell tests (?), so I added a skip-if

I think you can do this https://searchfox.org/mozilla-central/rev/a0ebb2a2c286c1d98d7ae93d043f65ed9970108b/dom/localstorage/test/unit/xpcshell.toml#85

(In reply to Marco Bonardo [:mak] from comment #44)

I think you can do this https://searchfox.org/mozilla-central/rev/a0ebb2a2c286c1d98d7ae93d043f65ed9970108b/dom/localstorage/test/unit/xpcshell.toml#85

Thank you, that's great to know!

Here's what that link points to, for posterity and making bug searching easier. requesttimeoutfactor is an xpcshell.toml option:

["test_snapshotting.js"]
skip-if = ["tsan"] # Unreasonably slow, bug 1612707
requesttimeoutfactor = 4
Pushed by dwillcoxon@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/45447fcb0116
Fix failures in urlbar weather tests. r=daisuke
Blocks: 1884854
Status: ASSIGNED → RESOLVED
Closed: 5 months ago4 months ago
Resolution: --- → FIXED
Target Milestone: --- → 125 Branch
See Also: → 1885264
Whiteboard: [stockwell disable-recommended] → [stockwell disable-recommended][sng]
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: