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)
Tracking
(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
Comment hidden (Intermittent Failures Robot) |
Comment 2•3 years ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.
Reporter | ||
Comment 3•3 years ago
|
||
treeherder |
New failure instance: https://treeherder.mozilla.org/logviewer?job_id=368374629&repo=autoland
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 9•3 years ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.
Updated•3 years ago
|
Reporter | ||
Comment 10•3 years ago
|
||
treeherder |
New failure instance: https://treeherder.mozilla.org/logviewer?job_id=374281897&repo=mozilla-central
Updated•3 years ago
|
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 17•3 years ago
|
||
There are 41 total failures in the last 7 days on
- linux1804-64-asan-qr opt
Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=379234393&repo=autoland&lineNumber=47312
[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!
Updated•3 years ago
|
Comment 18•2 years ago
|
||
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?
Comment 19•2 years ago
|
||
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?
Comment hidden (Intermittent Failures Robot) |
Comment 21•2 years ago
|
||
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:
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.
Assignee | ||
Comment 22•2 years ago
|
||
(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-75546But 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?
Assignee | ||
Comment 23•2 years ago
|
||
Assignee | ||
Comment 24•2 years ago
|
||
Comment 25•2 years ago
|
||
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 :)
Comment 26•2 years ago
|
||
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?
Comment 27•2 years ago
|
||
Updated•2 years ago
|
Comment hidden (Intermittent Failures Robot) |
Assignee | ||
Comment 29•2 years ago
|
||
(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?
Comment 30•2 years ago
|
||
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.
Assignee | ||
Comment 31•2 years ago
•
|
||
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
Assignee | ||
Comment 32•2 years ago
|
||
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.
Assignee | ||
Comment 33•2 years ago
|
||
Disabling scrollbars fixes the intermittent, also removing the skip-if since it always evaluated to false anyway.
Comment 34•2 years ago
|
||
According to the backfills/retriggers it seems to be failing quite a lot - backfill range
Comment hidden (Intermittent Failures Robot) |
Updated•2 years ago
|
Comment 36•2 years ago
|
||
Assignee | ||
Updated•2 years ago
|
Updated•2 years ago
|
Comment 37•2 years ago
|
||
Cosmin, is there a reason why we would have to leave the bug open? The landed patch fixes the test for real.
Comment 38•2 years ago
•
|
||
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.
Comment 39•2 years ago
|
||
bugherder |
Updated•2 years ago
|
Updated•2 years ago
|
Updated•2 years ago
|
Updated•2 years ago
|
Comment hidden (Intermittent Failures Robot) |
Assignee | ||
Comment 41•2 years ago
|
||
Removing the whiteboard flag, no new failure since the fix landed.
Assignee | ||
Updated•2 years ago
|
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 46•2 years ago
|
||
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.
Comment hidden (Intermittent Failures Robot) |
Updated•2 years ago
|
Comment 48•2 years ago
|
||
bugherder uplift |
Comment hidden (Intermittent Failures Robot) |
Updated•2 years ago
|
Comment 50•2 years ago
|
||
Description
•