Closed
Bug 1791988
Opened 2 years ago
Closed 2 years ago
Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_reftest.py TestReftest.test_cache_multiple_sizes | AssertionError: 'PASS' != 'TIMEOUT'
Categories
(Testing :: Marionette Client and Harness, defect, P5)
Testing
Marionette Client and Harness
Tracking
(Not tracked)
RESOLVED
WORKSFORME
People
(Reporter: intermittent-bug-filer, Unassigned)
References
Details
(Keywords: assertion, intermittent-failure)
Filed by: smolnar [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=391152032&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/CaSvgCq9TjKwaBGF2dLHFQ/runs/0/artifacts/public/logs/live_backing.log
INFO - 1663843442612 Marionette DEBUG Window URL does not match the expected URL "http://127.0.0.1:49873/reftest/mostly-teal-700x700.html" !== "http://127.0.0.1:49873/reftest/teal-700x700.html"
[task 2022-09-22T10:44:02.616Z] 10:44:02 INFO - [Parent 6604, Main Thread] WARNING: '!CanHandleWith(aPresContext)', file /builds/worker/checkouts/gecko/dom/events/IMEStateManager.cpp:498
[task 2022-09-22T10:44:02.618Z] 10:44:02 INFO - [Child 1124, Main Thread] WARNING: '!scrollbar', file /builds/worker/checkouts/gecko/widget/Theme.cpp:1071
[task 2022-09-22T10:44:02.620Z] 10:44:02 INFO - [Child 1124, Main Thread] WARNING: '!CanHandleWith(aPresContext)', file /builds/worker/checkouts/gecko/dom/events/IMEStateManager.cpp:498
[task 2022-09-22T10:44:02.626Z] 10:44:02 INFO - [Parent 6604, Main Thread] WARNING: 'aOwner->IsDiscarded()', file /builds/worker/workspace/obj-build/dist/include/mozilla/dom/SyncedContextInlines.h:95
[task 2022-09-22T10:44:02.630Z] 10:44:02 INFO - [GPU 664, Compositor] WARNING: Possibly dropping task posted to updater thread: file /builds/worker/checkouts/gecko/gfx/layers/apz/src/APZUpdater.cpp:371
[task 2022-09-22T10:44:02.633Z] 10:44:02 INFO - 1663843442633 Marionette TRACE Received observer notification xul-window-destroyed
[task 2022-09-22T10:44:02.635Z] 10:44:02 INFO - 1663843442635 Marionette DEBUG 6 <- [1,22,null,{"value":{"status":"TIMEOUT","message":null,"extra":{}}}]
[task 2022-09-22T10:44:02.640Z] 10:44:02 INFO - 1663843442643 Marionette DEBUG Canvas pool (600x600) is of length 0
[task 2022-09-22T10:44:02.645Z] 10:44:02 INFO - 1663843442647 Marionette DEBUG 6 -> [0,23,"Marionette:GetContext",{}]
[task 2022-09-22T10:44:02.649Z] 10:44:02 INFO - 1663843442648 Marionette DEBUG 6 <- [1,23,null,{"value":"content"}]
[task 2022-09-22T10:44:02.650Z] 10:44:02 INFO - 1663843442653 Marionette DEBUG 6 -> [0,24,"Marionette:SetContext",{"value":"chrome"}]
[task 2022-09-22T10:44:02.655Z] 10:44:02 INFO - 1663843442655 Marionette DEBUG 6 <- [1,24,null,{"value":null}]
[task 2022-09-22T10:44:02.656Z] 10:44:02 INFO - 1663843442658 Marionette DEBUG 6 -> [0,25,"WebDriver:TakeScreenshot",{"id":null,"full":true,"hash":false,"scroll":true}]
[task 2022-09-22T10:44:02.719Z] 10:44:02 INFO - 1663843442718 Marionette DEBUG 6 <- [1,25,null,{"value":"iVBORw0KGgoAAAANSUhEUgAABQAAAAP/CAYAAACf8GEBAAAgAElEQVR4XuzdCbRkZXUv8O/2PNHNJDK0iMpkHiKCAgrO+hbRFcREjVGjxjFK4hTHrBWn+J5ijFM0R ... AgAABAgQIECBAgAABAgQIECDQBRyA3U6SAAECBAgQIECAAAECBAgQIECAwL2AA/B+IgUJECBAgAABAgQIECBAgAABAgQIdIEB882vSxT/yrIAAAAASUVORK5CYII="}]
[task 2022-09-22T10:44:02.732Z] 10:44:02 INFO - 1663843442733 Marionette DEBUG 6 -> [0,26,"Marionette:SetContext",{"value":"content"}]
[task 2022-09-22T10:44:02.735Z] 10:44:02 INFO - 1663843442734 Marionette DEBUG 6 <- [1,26,null,{"value":null}]
[task 2022-09-22T10:44:02.737Z] 10:44:02 INFO - 1663843442737 Marionette DEBUG 6 -> [0,27,"Marionette:GetContext",{}]
[task 2022-09-22T10:44:02.738Z] 10:44:02 INFO - 1663843442737 Marionette DEBUG 6 <- [1,27,null,{"value":"content"}]
[task 2022-09-22T10:44:02.743Z] 10:44:02 INFO - 1663843442742 Marionette DEBUG 6 -> [0,28,"Marionette:SetContext",{"value":"content"}]
[task 2022-09-22T10:44:02.743Z] 10:44:02 INFO - 1663843442743 Marionette DEBUG 6 <- [1,28,null,{"value":null}]
[task 2022-09-22T10:44:02.747Z] 10:44:02 INFO - 1663843442747 Marionette DEBUG 6 -> [0,29,"WebDriver:GetPageSource",{}]
[task 2022-09-22T10:44:02.758Z] 10:44:02 INFO - [Child 1124, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp:3359
[task 2022-09-22T10:44:02.759Z] 10:44:02 INFO - [2022-09-22T10:44:02Z WARN audioipc2::ipccore] AudioIPC Server RPC: EventLoop drop - closing connection for Token(4) failed: Custom { kind: NotFound, error: "I/O source not registered with `Registry`" }
[task 2022-09-22T10:44:02.759Z] 10:44:02 INFO - [Child 1124, Main Thread] WARNING: NS_ENSURE_TRUE(InitStaticMembers()) failed: file /builds/worker/workspace/obj-build/dist/include/mozilla/Preferences.h:129
[task 2022-09-22T10:44:02.760Z] 10:44:02 INFO - 1663843442758 Marionette TRACE [3] MarionetteCommands actor created for window id 4294967297
[task 2022-09-22T10:44:02.766Z] 10:44:02 INFO - [Child 1124, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:4630
[task 2022-09-22T10:44:02.981Z] 10:44:02 INFO - 1663843442982 Marionette DEBUG 6 <- [1,29,null,{"value":"<html><head></head><body></body></html>"}]
[task 2022-09-22T10:44:02.992Z] 10:44:02 INFO - 1663843442992 Marionette DEBUG 6 -> [0,30,"Marionette:SetContext",{"value":"content"}]
[task 2022-09-22T10:44:02.993Z] 10:44:02 INFO - 1663843442993 Marionette DEBUG 6 <- [1,30,null,{"value":null}]
[task 2022-09-22T10:44:02.999Z] 10:44:02 ERROR - TEST-UNEXPECTED-FAIL | testing/marionette/harness/marionette_harness/tests/unit/test_reftest.py TestReftest.test_cache_multiple_sizes | AssertionError: 'PASS' != 'TIMEOUT'
[task 2022-09-22T10:44:03.000Z] 10:44:03 INFO - - PASS
[task 2022-09-22T10:44:03.000Z] 10:44:03 INFO - + TIMEOUT
[task 2022-09-22T10:44:03.000Z] 10:44:03 INFO - Traceback (most recent call last):
[task 2022-09-22T10:44:03.000Z] 10:44:03 INFO - File "Z:\task_166383992203247\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 202, in run
[task 2022-09-22T10:44:03.001Z] 10:44:03 INFO - testMethod()
INFO - File "Z:\task_166383992203247\build\tests\marionette\tests\testing\marionette\harness\marionette_harness\tests\unit\test_reftest.py", line 93, in test_cache_multiple_sizes
[task 2022-09-22T10:44:03.001Z] 10:44:03 INFO - self.assertEqual(u"PASS", rv[u"value"][u"status"])
[task 2022-09-22T10:44:03.002Z] 10:44:03 INFO - TEST-INFO took 10512ms
[task 2022-09-22T10:44:03.002Z] 10:44:03 INFO - 1663843443001 Marionette DEBUG 6 -> [0,31,"reftest:teardown",{}]
[task 2022-09-22T10:44:03.003Z] 10:44:03 INFO - 1663843443002 Marionette DEBUG 6 <- [1,31,null,{"value":null}]
[task 2022-09-22T10:44:03.004Z] 10:44:03 INFO - 1663843443003 Marionette DEBUG 6 -> [0,32,"WebDriver:SwitchToWindow",{"handle":"06580ec1-a068-4d72-99ea-f25b31064af8","focus":true}]
[task 2022-09-22T10:44:03.005Z] 10:44:03 INFO - 1663843443005 Marionette DEBUG 6 <- [1,32,null,{"value":null}]
[task 2022-09-22T10:44:03.007Z] 10:44:03 INFO - 1663843443007 Marionette DEBUG 6 -> [0,33,"Marionette:GetContext",{}]
[task 2022-09-22T10:44:03.008Z] 10:44:03 INFO - 1663843443008 Marionette DEBUG 6 <- [1,33,null,{"value":"content"}]
[task 2022-09-22T10:44:03.010Z] 10:44:03 INFO - 1663843443009 Marionette DEBUG 6 -> [0,34,"Marionette:SetContext",{"value":"chrome"}]
|
||
Comment 1•2 years ago
|
||
The expected target URL never gets loaded:
https://treeherder.mozilla.org/logviewer?job_id=391152032&repo=mozilla-central
task 2022-09-22T10:43:52.917Z] 10:43:52 INFO - 1663843432915 Marionette DEBUG Starting load of http://127.0.0.1:49873/reftest/teal-700x700.html
[task 2022-09-22T10:43:52.918Z] 10:43:52 INFO - [Parent 6604, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, false) failed with result 0x804B0051 (NS_ERROR_HOST_IS_IP_ADDRESS): file /builds/worker/checkouts/gecko/toolkit/components/antitracking/URLQueryStringStripper.cpp:150
[task 2022-09-22T10:43:52.920Z] 10:43:52 INFO - 1663843432919 Marionette DEBUG Window URL does not match the expected URL "http://127.0.0.1:49873/reftest/mostly-teal-700x700.html" !== "http://127.0.0.1:49873/reftest/teal-700x700.html"
[..]
[task 2022-09-22T10:44:02.612Z] 10:44:02 INFO - 1663843442612 Marionette DEBUG Window URL does not match the expected URL "http://127.0.0.1:49873/reftest/mostly-teal-700x700.html" !== "http://127.0.0.1:49873/reftest/teal-700x700.html"
[task 2022-09-22T10:44:02.616Z] 10:44:02 INFO - [Parent 6604, Main Thread] WARNING: '!CanHandleWith(aPresContext)', file /builds/worker/checkouts/gecko/dom/events/IMEStateManager.cpp:498
[task 2022-09-22T10:44:02.618Z] 10:44:02 INFO - [Child 1124, Main Thread] WARNING: '!scrollbar', file /builds/worker/checkouts/gecko/widget/Theme.cpp:1071
[task 2022-09-22T10:44:02.620Z] 10:44:02 INFO - [Child 1124, Main Thread] WARNING: '!CanHandleWith(aPresContext)', file /builds/worker/checkouts/gecko/dom/events/IMEStateManager.cpp:498
[task 2022-09-22T10:44:02.626Z] 10:44:02 INFO - [Parent 6604, Main Thread] WARNING: 'aOwner->IsDiscarded()', file /builds/worker/workspace/obj-build/dist/include/mozilla/dom/SyncedContextInlines.h:95
[task 2022-09-22T10:44:02.630Z] 10:44:02 INFO - [GPU 664, Compositor] WARNING: Possibly dropping task posted to updater thread: file /builds/worker/checkouts/gecko/gfx/layers/apz/src/APZUpdater.cpp:371
[task 2022-09-22T10:44:02.633Z] 10:44:02 INFO - 1663843442633 Marionette TRACE Received observer notification xul-window-destroyed
[task 2022-09-22T10:44:02.635Z] 10:44:02 INFO - 1663843442635 Marionette DEBUG 6 <- [1,22,null,{"value":{"status":"TIMEOUT","message":null,"extra":{}}}]
The isReftestReady is performed without a delay and spams the log quite a lot. I'm also not sure if it helps performance when it is maybe blocking the main thread? James should we maybe add a small sleep of 100ms here?
Also the code works with the formerly retrieved browsing context. If there is a replacement it would actually wait forever. As such I would propose the webProgress should be fetched first and webProgress.browsingContext be used to always have the up-to-date one.
Flags: needinfo?(james)
|
||
Comment 2•2 years ago
|
||
Historically people have been very worried about reftest performance, so adding in extra sleeps would be considered a serious regression.
Given that setting isReftestReady involves an awaiting an IPC message to a JSWindowActor, I don't think it ought to be blocking anything? We only return false if we've loaded something other than the test URL. But it seems plausible that if the navigation changes browsingContext then we should ensure we're using the new browsing context for each iteration. Is that something you could provide a patch for?
Flags: needinfo?(james) → needinfo?(hskupin)
| Comment hidden (Intermittent Failures Robot) |
|
|
||
Comment 4•2 years ago
|
||
The patch on bug 1794553 should have fixed it. Given that it rarely fails and I'm not able to reproduce the issue locally I'm going to mark this bug as WFM so that it can be re-opened in case it hasn't been fixed.
Status: NEW → RESOLVED
Closed: 2 years ago
Flags: needinfo?(hskupin)
Resolution: --- → WORKSFORME
|
||
Updated•2 years ago
|
Product: Testing → Remote Protocol
|
|
||
Comment 5•2 years ago
|
||
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.
Description
•