Closed Bug 1727207 Opened 3 years ago Closed 2 years ago

High freq Linux ASAN testing/marionette/harness/marionette_harness/tests/unit/test_reftest.py TestReftest.test_cache_multiple_sizes | AssertionError: 'PASS' != 'FAIL'

Categories

(Testing :: Marionette Client and Harness, defect, P1)

defect
Points:
1

Tracking

(firefox-esr102 fixed, firefox102 wontfix, firefox103 fixed)

RESOLVED FIXED
103 Branch
Tracking Status
firefox-esr102 --- fixed
firefox102 --- wontfix
firefox103 --- fixed

People

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

References

(Blocks 1 open bug)

Details

(Keywords: assertion, intermittent-failure, Whiteboard: [webdriver:m4][webdriver:external][stockwell disable-recommended])

Attachments

(3 files, 1 obsolete file)

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


[task 2021-08-23T22:44:12.180Z] 22:44:12     INFO -  1629758652180	Marionette	DEBUG	25 <- [1,23,null,{"value":null}]
[task 2021-08-23T22:44:12.182Z] 22:44:12    ERROR -  TEST-UNEXPECTED-FAIL | testing/marionette/harness/marionette_harness/tests/unit/test_reftest.py TestReftest.test_cache_multiple_sizes | AssertionError: 'PASS' != 'FAIL'
[task 2021-08-23T22:44:12.182Z] 22:44:12     INFO -  - PASS
[task 2021-08-23T22:44:12.182Z] 22:44:12     INFO -  + FAIL
[task 2021-08-23T22:44:12.182Z] 22:44:12     INFO -  Traceback (most recent call last):
[task 2021-08-23T22:44:12.182Z] 22:44:12     INFO -    File "C:\Users\task_1629748997\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 202, in run
[task 2021-08-23T22:44:12.182Z] 22:44:12     INFO -      testMethod()
[task 2021-08-23T22:44:12.183Z] 22:44:12     INFO -    File "C:\Users\task_1629748997\build\tests\marionette\tests\testing\marionette\harness\marionette_harness\tests\unit\test_reftest.py", line 91, in test_cache_multiple_sizes
[task 2021-08-23T22:44:12.183Z] 22:44:12     INFO -      self.assertEqual(u"PASS", rv[u"value"][u"status"])
[task 2021-08-23T22:44:12.183Z] 22:44:12     INFO -  TEST-INFO took 555ms
Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 3 years ago3 years ago
Resolution: --- → INCOMPLETE
Summary: Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_reftest.py TestReftest.test_cache_multiple_sizes | AssertionError: 'PASS' != 'FAIL' → Intermittent [tier2] testing/marionette/harness/marionette_harness/tests/unit/test_reftest.py TestReftest.test_cache_multiple_sizes | AssertionError: 'PASS' != 'FAIL'
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Summary: Intermittent [tier2] testing/marionette/harness/marionette_harness/tests/unit/test_reftest.py TestReftest.test_cache_multiple_sizes | AssertionError: 'PASS' != 'FAIL' → Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_reftest.py TestReftest.test_cache_multiple_sizes | AssertionError: 'PASS' != 'FAIL'

There are 41 total failures in the last 7 days on

[task 2022-05-25T10:56:49.437Z] 10:56:49     INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_reftest.py TestReftest.test_cache_multiple_sizes
[task 2022-05-25T10:56:49.438Z] 10:56:49     INFO -  1653476209435	Marionette	DEBUG	Closed connection 23
[task 2022-05-25T10:56:49.441Z] 10:56:49     INFO -  1653476209436	Marionette	DEBUG	Accepted connection 24 from 127.0.0.1:49954
[task 2022-05-25T10:56:49.444Z] 10:56:49     INFO -  1653476209438	Marionette	DEBUG	24 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2022-05-25T10:56:49.447Z] 10:56:49     INFO -  1653476209439	Marionette	DEBUG	Waiting for initial application window
[task 2022-05-25T10:56:49.450Z] 10:56:49     INFO -  1653476209442	RemoteAgent	TRACE	[64] Document already finished loading: data:text/html;charset=utf-8,%3Cselect%20multiple%3E%20%3Coption%3Efirst%20%3C/select%3E
[task 2022-05-25T10:56:49.453Z] 10:56:49     INFO -  1653476209446	Marionette	DEBUG	24 <- [1,1,null,{"sessionId":"5dff837a-dfb9-452e-8159-a9604b5185b7","capabilities":{"browserName":"firefox","browserVersion":"102.0 ... wnTimeout":300000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"moz:windowless":false,"proxy":{}}}]
[task 2022-05-25T10:56:49.456Z] 10:56:49     INFO -  1653476209449	Marionette	DEBUG	24 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2022-05-25T10:56:49.458Z] 10:56:49     INFO -  1653476209450	Marionette	DEBUG	24 <- [1,2,null,{"value":null}]
[task 2022-05-25T10:56:49.461Z] 10:56:49     INFO -  1653476209451	Marionette	DEBUG	24 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2022-05-25T10:56:49.463Z] 10:56:49     INFO -  1653476209452	Marionette	DEBUG	24 <- [1,3,null,{"value":null}]
[task 2022-05-25T10:56:49.466Z] 10:56:49     INFO -  1653476209454	Marionette	DEBUG	24 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2022-05-25T10:56:49.468Z] 10:56:49     INFO -  1653476209454	Marionette	DEBUG	24 <- [1,4,null,{"value":null}]
[task 2022-05-25T10:56:49.471Z] 10:56:49     INFO -  1653476209457	Marionette	DEBUG	24 -> [0,5,"Marionette:GetContext",{}]
[task 2022-05-25T10:56:49.474Z] 10:56:49     INFO -  1653476209458	Marionette	DEBUG	24 <- [1,5,null,{"value":"content"}]
[task 2022-05-25T10:56:49.476Z] 10:56:49     INFO -  1653476209460	Marionette	DEBUG	24 -> [0,6,"Marionette:SetContext",{"value":"content"}]
[task 2022-05-25T10:56:49.478Z] 10:56:49     INFO -  1653476209460	Marionette	DEBUG	24 <- [1,6,null,{"value":null}]
[task 2022-05-25T10:56:49.480Z] 10:56:49     INFO -  1653476209462	Marionette	DEBUG	24 -> [0,7,"WebDriver:GetWindowHandle",{}]
[task 2022-05-25T10:56:49.482Z] 10:56:49     INFO -  1653476209463	Marionette	DEBUG	24 <- [1,7,null,{"value":"1e1d39d5-be0e-4be6-b2f6-eae236583067"}]
[task 2022-05-25T10:56:49.484Z] 10:56:49     INFO -  1653476209465	Marionette	DEBUG	24 -> [0,8,"Marionette:SetContext",{"value":"content"}]
[task 2022-05-25T10:56:49.486Z] 10:56:49     INFO -  1653476209466	Marionette	DEBUG	24 <- [1,8,null,{"value":null}]
[task 2022-05-25T10:56:49.489Z] 10:56:49     INFO -  1653476209469	Marionette	DEBUG	24 -> [0,9,"Marionette:GetContext",{}]
[task 2022-05-25T10:56:49.491Z] 10:56:49     INFO -  1653476209470	Marionette	DEBUG	24 <- [1,9,null,{"value":"content"}]
[task 2022-05-25T10:56:49.493Z] 10:56:49     INFO -  1653476209471	Marionette	DEBUG	24 -> [0,10,"Marionette:SetContext",{"value":"chrome"}]
[task 2022-05-25T10:56:49.496Z] 10:56:49     INFO -  1653476209472	Marionette	DEBUG	24 <- [1,10,null,{"value":null}]
[task 2022-05-25T10:56:49.498Z] 10:56:49     INFO -  1653476209475	Marionette	DEBUG	24 -> [0,11,"WebDriver:ExecuteScript",{"script":"const { Preferences } = ChromeUtils.import(\n                  \"resource://gre/mo ... ox":true,"sandbox":"default","line":849,"filename":"../../venv/lib/python3.6/site-packages/marionette_driver/marionette.py"}]
[task 2022-05-25T10:56:49.500Z] 10:56:49     INFO -  1653476209482	Marionette	TRACE	[7] MarionetteCommands actor created for window id 2
[task 2022-05-25T10:56:49.503Z] 10:56:49     INFO -  1653476209498	Marionette	DEBUG	24 <- [1,11,null,{"value":null}]
[task 2022-05-25T10:56:49.505Z] 10:56:49     INFO -  1653476209501	Marionette	DEBUG	24 -> [0,12,"Marionette:SetContext",{"value":"content"}]
[task 2022-05-25T10:56:49.508Z] 10:56:49     INFO -  1653476209503	Marionette	DEBUG	24 <- [1,12,null,{"value":null}]
[task 2022-05-25T10:56:49.510Z] 10:56:49     INFO -  1653476209505	Marionette	DEBUG	24 -> [0,13,"Marionette:GetContext",{}]
[task 2022-05-25T10:56:49.513Z] 10:56:49     INFO -  1653476209506	Marionette	DEBUG	24 <- [1,13,null,{"value":"content"}]
[task 2022-05-25T10:56:49.515Z] 10:56:49     INFO -  1653476209508	Marionette	DEBUG	24 -> [0,14,"Marionette:SetContext",{"value":"chrome"}]
[task 2022-05-25T10:56:49.517Z] 10:56:49     INFO -  1653476209509	Marionette	DEBUG	24 <- [1,14,null,{"value":null}]
[task 2022-05-25T10:56:49.520Z] 10:56:49     INFO -  1653476209512	Marionette	DEBUG	24 -> [0,15,"WebDriver:ExecuteScript",{"script":"const { Preferences } = ChromeUtils.import(\n                  \"resource://gre/mo ... ox":true,"sandbox":"default","line":849,"filename":"../../venv/lib/python3.6/site-packages/marionette_driver/marionette.py"}]
[task 2022-05-25T10:56:49.546Z] 10:56:49     INFO -  1653476209546	Marionette	DEBUG	24 <- [1,15,null,{"value":null}]
[task 2022-05-25T10:56:49.554Z] 10:56:49     INFO -  1653476209553	Marionette	DEBUG	24 -> [0,16,"Marionette:SetContext",{"value":"content"}]
[task 2022-05-25T10:56:49.558Z] 10:56:49     INFO -  1653476209558	Marionette	DEBUG	24 <- [1,16,null,{"value":null}]
[task 2022-05-25T10:56:49.565Z] 10:56:49     INFO -  1653476209565	Marionette	DEBUG	24 -> [0,17,"reftest:setup",{"screenshot":"unexpected"}]
[task 2022-05-25T10:56:49.583Z] 10:56:49     INFO -  1653476209582	Marionette	DEBUG	24 <- [1,17,null,{"value":null}]
[task 2022-05-25T10:56:49.586Z] 10:56:49     INFO -  1653476209585	Marionette	DEBUG	24 -> [0,18,"reftest:run",{"test":"http://127.0.0.1:38182/reftest/teal-700x700.html","references":[["http://127.0.0.1:38182/reftest/mostly-teal-700x700.html",[],"=="]],"expected":"PASS","timeout":10000,"width":600,"height":600}]
[task 2022-05-25T10:56:49.587Z] 10:56:49     INFO -  1653476209587	Marionette	DEBUG	ensuring we have a window 600x600
[task 2022-05-25T10:56:49.588Z] 10:56:49     INFO -  1653476209587	Marionette	DEBUG	Using separate window
[task 2022-05-25T10:56:49.595Z] 10:56:49     INFO -  1653476209595	Marionette	TRACE	Received observer notification domwindowopened
[task 2022-05-25T10:56:49.692Z] 10:56:49     INFO -  1653476209691	RemoteAgent	TRACE	Received DOM event activate for [object Window]
[task 2022-05-25T10:56:49.694Z] 10:56:49     INFO -  1653476209692	RemoteAgent	TRACE	Received DOM event focus for [object HTMLDocument]
[task 2022-05-25T10:56:49.700Z] 10:56:49     INFO -  JavaScript error: chrome://remote/content/shared/TabManager.jsm, line 311: TypeError: can't access property "linkedBrowser", tab is undefined
[task 2022-05-25T10:56:49.701Z] 10:56:49     INFO -  1653476209701	Marionette	DEBUG	loaded initial URL: about:blank

[task 2022-05-25T10:56:51.706Z] 10:56:51     INFO -  1653476211706	Marionette	DEBUG	24 -> [0,25,"WebDriver:GetPageSource",{}]
[task 2022-05-25T10:56:51.716Z] 10:56:51     INFO -  1653476211715	Marionette	TRACE	[67] MarionetteCommands actor created for window id 10737418242
[task 2022-05-25T10:56:51.722Z] 10:56:51     INFO -  1653476211721	Marionette	DEBUG	24 <- [1,25,null,{"value":"<html><head><style>\n  * {\n      margin: 0;\n      padding: 0;\n  }\n\n  html {\n      background: teal ... ight: 100px;\n      width: 100px;\n      background: transparent;\n  }\n</style>\n</head><body><div></div>\n</body></html>"}]
[task 2022-05-25T10:56:51.726Z] 10:56:51     INFO -  1653476211725	Marionette	DEBUG	24 -> [0,26,"Marionette:SetContext",{"value":"content"}]
[task 2022-05-25T10:56:51.727Z] 10:56:51     INFO -  1653476211726	Marionette	DEBUG	24 <- [1,26,null,{"value":null}]
[task 2022-05-25T10:56:51.744Z] 10:56:51     INFO - TEST-UNEXPECTED-FAIL | testing/marionette/harness/marionette_harness/tests/unit/test_reftest.py TestReftest.test_cache_multiple_sizes | AssertionError: 'PASS' != 'FAIL'
[task 2022-05-25T10:56:51.744Z] 10:56:51     INFO - - PASS
[task 2022-05-25T10:56:51.744Z] 10:56:51     INFO - + FAIL
[task 2022-05-25T10:56:51.744Z] 10:56:51     INFO - Traceback (most recent call last):
[task 2022-05-25T10:56:51.744Z] 10:56:51     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_harness/marionette_test/testcases.py", line 202, in run
[task 2022-05-25T10:56:51.744Z] 10:56:51     INFO -     testMethod()
[task 2022-05-25T10:56:51.744Z] 10:56:51     INFO -   File "/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_reftest.py", line 91, in test_cache_multiple_sizes
[task 2022-05-25T10:56:51.744Z] 10:56:51     INFO -     self.assertEqual(u"PASS", rv[u"value"][u"status"])
[task 2022-05-25T10:56:51.744Z] 10:56:51     INFO - TEST-INFO took 2293ms

Glenn, could you please take a look or assign this to someone?
Thank you!

Flags: needinfo?(gwatson)
Whiteboard: [stockwell needswork:owner]

Hi Andreea, I'm not really sure what this failure means or even who would be good to look at it.

I think it comes from:

[task 2022-05-25T10:41:32.537Z] 10:41:32     INFO -  Assertion failure
[task 2022-05-25T10:41:32.538Z] 10:41:32     INFO -  assert@resource:///modules/AsyncTabSwitcher.jsm:500:36
[task 2022-05-25T10:41:32.539Z] 10:41:32     INFO -  onLayersCleared@resource:///modules/AsyncTabSwitcher.jsm:811:12
[task 2022-05-25T10:41:32.539Z] 10:41:32     INFO -  handleEvent@resource:///modules/AsyncTabSwitcher.jsm:1111:16

Emilio, any ideas what this means and/or who would be a good candidate to look at it?

Flags: needinfo?(gwatson) → needinfo?(emilio)

I don't think the tab switcher assert is relevant. Henrik are there screenshots that could help debug the retest failure or something like that? Or is this a marionette bug?

Component: Graphics: WebRender → Marionette
Flags: needinfo?(emilio) → needinfo?(hskupin)
Product: Core → Testing

So it looks like that only Linux ASAN builds are affected here and we saw an increase of test failures on autoland starting in the week of March 25th to May 2nd. But I cannot see that we changed something for Marionette for the 101 release. Maybe a regression check might be good here.

(In reply to Emilio Cobos Álvarez (:emilio) from comment #19)

I don't think the tab switcher assert is relevant. Henrik are there screenshots that could help debug the retest failure or something like that? Or is this a marionette bug?

Screenshots are taken as you can see here:
https://treeherder.mozilla.org/logviewer?job_id=379569697&repo=mozilla-central&lineNumber=75544-75546

But sadly we also truncate the line so the data URL is not usable. Someone could run a try build with the preference remote.log.truncate set to false. Otherwise you could also print the URL once received by Marionette here:

https://searchfox.org/mozilla-central/source/testing/marionette/harness/marionette_harness/runner/base.py#709-710

Maybe we could do this by default in such cases so help with debugging.

Otherwise I would defer to James who is more familiar with the appropriate code.

Status: REOPENED → NEW
Flags: needinfo?(hskupin) → needinfo?(james)
Summary: Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_reftest.py TestReftest.test_cache_multiple_sizes | AssertionError: 'PASS' != 'FAIL' → Intermittent Linux ASAN testing/marionette/harness/marionette_harness/tests/unit/test_reftest.py TestReftest.test_cache_multiple_sizes | AssertionError: 'PASS' != 'FAIL'

(In reply to Henrik Skupin (:whimboo) [⌚️UTC+1] from comment #21)

So it looks like that only Linux ASAN builds are affected here and we saw an increase of test failures on autoland starting in the week of March 25th to May 2nd. But I cannot see that we changed something for Marionette for the 101 release. Maybe a regression check might be good here.

(In reply to Emilio Cobos Álvarez (:emilio) from comment #19)

I don't think the tab switcher assert is relevant. Henrik are there screenshots that could help debug the retest failure or something like that? Or is this a marionette bug?

Screenshots are taken as you can see here:
https://treeherder.mozilla.org/logviewer?job_id=379569697&repo=mozilla-central&lineNumber=75544-75546

But sadly we also truncate the line so the data URL is not usable. Someone could run a try build with the preference remote.log.truncate set to false. Otherwise you could also print the URL once received by Marionette here:

I just did a run with truncate to false: https://treeherder.mozilla.org/jobs?repo=try&selectedTaskRun=DL_ADyb_Rka-aLSPOkfnkA.0&revision=f40bb43bbfedc494454c9cecf091e1683ed0c11e

I can attach the images for a failure, but basically the only difference is about the way the floating scrollbars are rendered. In one version their color is rgb(150, 163, 162), while in the other version it is rgb(163, 166, 165).

I can imagine that the scrollbars are progressively fading in/out, so the visible color used to draw them might be different depending on the timing of the test?

Attached image image1.png
Attached image image2.png

Well there's the question of why are we using overlay scrollbars at all too (I thought we disabled them for reftests generally), but anyways yeah, at least that's not too concerning :)

Well, this is from a Marionette unit test and those have different preferences set compared to web-platform reftests which only make use of Marionette. Which preference is this specifically? Can it be changed at runtime? We could specifically set it for this particular test. Or what would be the differences / implications if we do in for all Marionette?

Assignee: nobody → apavel
Status: NEW → ASSIGNED

(In reply to Emilio Cobos Álvarez (:emilio) from comment #25)

Well there's the question of why are we using overlay scrollbars at all too (I thought we disabled them for reftests generally), but anyways yeah, at least that's not too concerning :)

Henrik mentioned this is a Marionette unit test, so we might miss a preference to disable the scrollbars. Do you remember which preference we could set here to avoid having scrollbars?

Flags: needinfo?(emilio)

On Linux, it's this: https://searchfox.org/mozilla-central/rev/c8e15e17bc6fd28f558c395c948a6251b38774ff/testing/profiles/common/user.js#89

On macOS and Windows they should be disabled at the system level.

Flags: needinfo?(emilio)

Thanks! I can see it's still set to true when running Marionette unit tests.
Here's a try push forcing it to false: https://treeherder.mozilla.org/jobs?repo=try&revision=5fab95d955e0c75895561887891dc1e981b6b649

Edit: wrong try push, I had a typo in the preference name. New push: https://treeherder.mozilla.org/#/jobs?repo=try&revision=d636124352d94e43712c9ab598e5f7ff05c20dca

As commented on https://phabricator.services.mozilla.com/D148090, the current skip-if is probably not working as expected: os == "linux" && asan && fission. fission cannot be found in the mozinfo for this test, so it makes the condition fail.

Disabling scrollbars fixes the intermittent, also removing the skip-if since it always evaluated to false anyway.

According to the backfills/retriggers it seems to be failing quite a lot - backfill range

Summary: Intermittent Linux ASAN testing/marionette/harness/marionette_harness/tests/unit/test_reftest.py TestReftest.test_cache_multiple_sizes | AssertionError: 'PASS' != 'FAIL' → High freq Linux ASAN testing/marionette/harness/marionette_harness/tests/unit/test_reftest.py TestReftest.test_cache_multiple_sizes | AssertionError: 'PASS' != 'FAIL'
Attachment #9279427 - Attachment description: Bug 1727207 - [marionette] Disable widget.gtk.overlay-scrollbars.enabled for marionette unit tests → Bug 1727207 - [marionette] Disable widget.gtk.overlay-scrollbars.enabled for test_reftest.py
Blocks: 1772478
Pushed by jdescottes@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/d3911aa2553b [marionette] Disable widget.gtk.overlay-scrollbars.enabled for test_reftest.py r=webdriver-reviewers,whimboo
Points: --- → 1
Priority: P5 → P1
Whiteboard: [stockwell disable-recommended] → [webdriver:m4][stockwell disable-recommended][webdriver:external]
Keywords: leave-open
Whiteboard: [webdriver:m4][stockwell disable-recommended][webdriver:external] → [webdriver:m4][stockwell disabled][webdriver:external]

Cosmin, is there a reason why we would have to leave the bug open? The landed patch fixes the test for real.

Flags: needinfo?(james) → needinfo?(csabou)

If it fixes then yes I'll delete the tags. Given the commit I thought it was just disabled, my bad. Thanks for pointing that out.

Flags: needinfo?(csabou)
Keywords: leave-open
Whiteboard: [webdriver:m4][stockwell disabled][webdriver:external] → [webdriver:m4][webdriver:external]
Status: ASSIGNED → RESOLVED
Closed: 3 years ago2 years ago
Resolution: --- → FIXED
Target Milestone: --- → 103 Branch
Points: 1 → ---
Attachment #9279364 - Attachment is obsolete: true
Assignee: apavel → nobody
Assignee: nobody → jdescottes

Removing the whiteboard flag, no new failure since the fix landed.

Whiteboard: [webdriver:m4][webdriver:external][stockwell disable-recommended] → [webdriver:m4][webdriver:external]
Points: --- → 1

Release is affected as well (see the just duplicated bug) but not sure if we are going to fix that if the volume of failures is low.

Product: Testing → Remote Protocol
Moving bug to Testing::Marionette Client and Harness component per bug 1815831.
Component: Marionette → Marionette Client and Harness
Product: Remote Protocol → Testing
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: