Closed Bug 1817124 Opened 2 years ago Closed 2 years ago

High frequency testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestNavigate.test_focus_after_navigation | marionette_driver.errors.NoSuchElementException: Unable to locate element: :focus

Categories

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

defect

Tracking

(firefox-esr102 unaffected, firefox110 unaffected, firefox111 unaffected, firefox112 fixed)

RESOLVED FIXED
112 Branch
Tracking Status
firefox-esr102 --- unaffected
firefox110 --- unaffected
firefox111 --- unaffected
firefox112 --- fixed

People

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

References

(Regression)

Details

(Keywords: intermittent-failure, regression, Whiteboard: [retriggered])

Attachments

(1 file)

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


INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestNavigate.test_focus_after_navigation
[task 2023-02-15T21:12:55.560Z] 21:12:55     INFO -  1676495575560	Marionette	DEBUG	Accepted connection 543 from 127.0.0.1:50033
[task 2023-02-15T21:12:55.560Z] 21:12:55     INFO -  1676495575560	Marionette	DEBUG	543 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2023-02-15T21:12:55.561Z] 21:12:55     INFO -  1676495575560	Marionette	DEBUG	Waiting for initial application window
[task 2023-02-15T21:12:55.561Z] 21:12:55     INFO -  1676495575561	RemoteAgent	TRACE	[535] ProgressListener Start: expectNavigation=false resolveWhenStarted=false unloadTimeout=200 waitForExplicitStart=false
[task 2023-02-15T21:12:55.561Z] 21:12:55     INFO -  1676495575561	RemoteAgent	TRACE	[535] ProgressListener Setting unload timer (200ms)
[task 2023-02-15T21:12:55.561Z] 21:12:55     INFO -  1676495575561	RemoteAgent	TRACE	[535] Document already finished loading: http://127.0.0.1:49234/test.html
[task 2023-02-15T21:12:55.562Z] 21:12:55     INFO -  1676495575561	RemoteAgent	TRACE	[535] ProgressListener Stop: has error=false
[task 2023-02-15T21:12:55.562Z] 21:12:55     INFO -  1676495575562	Marionette	DEBUG	543 <- [1,1,null,{"sessionId":"070238ff-a849-4afc-9b8a-f75f568d48cf","capabilities":{"browserName":"firefox","browserVersion":"112.0a1","platformName":"mac","acceptInsecureCerts":false,"pageLoadStrategy":"normal","setWindowRect":true,"timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"strictFileInteractability":true,"unhandledPromptBehavior":"dismiss and notify","moz:accessibilityChecks":false,"moz:buildID":"20230215202750","moz:headless":false,"moz:platformVersion":"19.6.0","moz:processID":1107,"moz:profile":"/var/folders/l4/gqq0rv4x3252x7yrx9lgp66r000014/T/tmp3o6i9p6w.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"moz:windowless":false,"proxy":{}}}]
[task 2023-02-15T21:12:55.563Z] 21:12:55     INFO -  1676495575562	Marionette	DEBUG	543 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
<...>
INFO -  DEBUG: Adding blocker ContentParent: id=12c2d1000 for phase quit-application-granted
[task 2023-02-15T21:12:58.012Z] 21:12:58     INFO -  1676495578012	Marionette	DEBUG	1 -> [0,9,"Marionette:GetContext",{}]
[task 2023-02-15T21:12:58.012Z] 21:12:58     INFO -  1676495578012	Marionette	DEBUG	1 <- [1,9,null,{"value":"content"}]
[task 2023-02-15T21:12:58.014Z] 21:12:58     INFO -  1676495578013	Marionette	DEBUG	1 -> [0,10,"Marionette:SetContext",{"value":"content"}]
[task 2023-02-15T21:12:58.014Z] 21:12:58     INFO -  1676495578014	Marionette	DEBUG	1 <- [1,10,null,{"value":null}]
[task 2023-02-15T21:12:58.015Z] 21:12:58     INFO -  1676495578015	Marionette	DEBUG	1 -> [0,11,"WebDriver:GetPageSource",{}]
[task 2023-02-15T21:12:58.016Z] 21:12:58     INFO -  1676495578015	Marionette	DEBUG	1 <- [1,11,null,{"value":"<html><head></head><body><input autofocus=\"\"></body></html>"}]
[task 2023-02-15T21:12:58.016Z] 21:12:58     INFO -  1676495578016	Marionette	DEBUG	1 -> [0,12,"Marionette:SetContext",{"value":"content"}]
[task 2023-02-15T21:12:58.017Z] 21:12:58     INFO -  1676495578016	Marionette	DEBUG	1 <- [1,12,null,{"value":null}]
[task 2023-02-15T21:12:58.095Z] 21:12:58     INFO - TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestNavigate.test_focus_after_navigation | marionette_driver.errors.NoSuchElementException: Unable to locate element: :focus
[task 2023-02-15T21:12:58.095Z] 21:12:58     INFO - stacktrace:
[task 2023-02-15T21:12:58.095Z] 21:12:58     INFO - 	RemoteError@chrome://remote/content/shared/RemoteError.sys.mjs:8:8
[task 2023-02-15T21:12:58.095Z] 21:12:58     INFO - 	WebDriverError@chrome://remote/content/shared/webdriver/Errors.sys.mjs:180:5
[task 2023-02-15T21:12:58.095Z] 21:12:58     INFO - 	NoSuchElementError@chrome://remote/content/shared/webdriver/Errors.sys.mjs:392:5
[task 2023-02-15T21:12:58.095Z] 21:12:58     INFO - 	element.find/</<@chrome://remote/content/marionette/element.sys.mjs:134:16
[task 2023-02-15T21:12:58.095Z] 21:12:58     INFO - Traceback (most recent call last):
[task 2023-02-15T21:12:58.096Z] 21:12:58     INFO -   File "/opt/worker/tasks/task_167649534374099/build/venv/lib/python3.7/site-packages/marionette_harness/marionette_test/testcases.py", line 198, in run
[task 2023-02-15T21:12:58.096Z] 21:12:58     INFO -     testMethod()
[task 2023-02-15T21:12:58.096Z] 21:12:58     INFO -   File "/opt/worker/tasks/task_167649534374099/build/venv/lib/python3.7/site-packages/marionette_harness/marionette_test/decorators.py", line 59, in skip_wrapper
[task 2023-02-15T21:12:58.096Z] 21:12:58     INFO -     return test_item(self, *args, **kwargs)
[task 2023-02-15T21:12:58.096Z] 21:12:58     INFO -   File "/opt/worker/tasks/task_167649534374099/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py", line 320, in test_focus_after_navigation
[task 2023-02-15T21:12:58.096Z] 21:12:58     INFO -     focus_el = self.marionette.find_element(By.CSS_SELECTOR, ":focus")
[task 2023-02-15T21:12:58.096Z] 21:12:58     INFO -   File "/opt/worker/tasks/task_167649534374099/build/venv/lib/python3.7/site-packages/marionette_driver/marionette.py", line 1843, in find_element
[task 2023-02-15T21:12:58.096Z] 21:12:58     INFO -     return self._send_message("WebDriver:FindElement", body, key="value")
[task 2023-02-15T21:12:58.096Z] 21:12:58     INFO -   File "/opt/worker/tasks/task_167649534374099/build/venv/lib/python3.7/site-packages/marionette_driver/decorators.py", line 24, in _
[task 2023-02-15T21:12:58.096Z] 21:12:58     INFO -     return func(*args, **kwargs)
[task 2023-02-15T21:12:58.096Z] 21:12:58     INFO -   File "/opt/worker/tasks/task_167649534374099/build/venv/lib/python3.7/site-packages/marionette_driver/marionette.py", line 663, in _send_message
[task 2023-02-15T21:12:58.096Z] 21:12:58     INFO -     self._handle_error(err)
[task 2023-02-15T21:12:58.096Z] 21:12:58     INFO -   File "/opt/worker/tasks/task_167649534374099/build/venv/lib/python3.7/site-packages/marionette_driver/marionette.py", line 675, in _handle_error
[task 2023-02-15T21:12:58.096Z] 21:12:58     INFO -     raise errors.lookup(error)(message, stacktrace=stacktrace)
[task 2023-02-15T21:12:58.096Z] 21:12:58     INFO - TEST-INFO took 2458ms
[task 2023-02-15T21:12:58.097Z] 21:12:58     INFO -  1676495578019	Marionette	DEBUG	1 -> [0,13,"WebDriver:SetTimeouts",{"script":30000}]
[task 2023-02-15T21:12:58.097Z] 21:12:58     INFO -  1676495578019	Marionette	DEBUG	1 <- [1,13,null,{"value":null}]
INFO -  1676495578020	Marionette	DEBUG	1 -> [0,14,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2023-02-15T21:12:58.097Z] 21:12:58     INFO -  1676495578020	Marionette	DEBUG	1 <- [1,14,null,{"value":null}]
[task 2023-02-15T21:12:58.098Z] 21:12:58     INFO -  1676495578021	Marionette	DEBUG	1 -> [0,15,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2023-02-15T21:12:58.098Z] 21:12:58     INFO -  1676495578021	Marionette	DEBUG	1 <- [1,15,null,{"value":null}]
[task 2023-02-15T21:12:58.098Z] 21:12:58     INFO -  1676495578023	Marionette	DEBUG	1 -> [0,16,"Marionette:GetContext",{}]
[task 2023-02-15T21:12:58.098Z] 21:12:58     INFO -  1676495578023	Marionette	DEBUG	1 <- [1,16,null,{"value":"content"}]
[task 2023-02-15T21:12:58.099Z] 21:12:58     INFO -  1676495578024	Marionette	DEBUG	1 -> [0,17,"Marionette:SetContext",{"value":"content"}]
[task 2023-02-15T21:12:58.099Z] 21:12:58     INFO -  1676495578024	Marionette	DEBUG	1 <- [1,17,null,{"value":null}]
[task 2023-02-15T21:12:58.099Z] 21:12:58     INFO -  1676495578024	Marionette	DEBUG	1 -> [0,18,"WebDriver:GetWindowHandles",{}]
[task 2023-02-15T21:12:58.099Z] 21:12:58     INFO -  1676495578024	Marionette	DEBUG	1 <- [1,18,null,["328a4df7-e9ac-4ab2-a6a5-5c9ec75e2557","a5a0cea7-4cd5-4f1b-b2b7-f9324047cf81"]]
[task 2023-02-15T21:12:58.100Z] 21:12:58     INFO -  1676495578025	Marionette	DEBUG	1 -> [0,19,"Marionette:SetContext",{"value":"content"}]
[task 2023-02-15T21:12:58.100Z] 21:12:58     INFO -  1676495578026	Marionette	DEBUG	1 <- [1,19,null,{"value":null}]
[task 2023-02-15T21:12:58.100Z] 21:12:58     INFO -  1676495578026	Marionette	DEBUG	1 -> [0,20,"WebDriver:SwitchToWindow",{"handle":"a5a0cea7-4cd5-4f1b-b2b7-f9324047cf81","focus":true}]
[task 2023-02-15T21:12:58.101Z] 21:12:58     INFO -  1676495578027	Marionette	DEBUG	1 <- [1,20,null,{"value":null}]
[task 2023-02-15T21:12:58.101Z] 21:12:58     INFO -  1676495578028	Marionette	DEBUG	1 -> [0,21,"WebDriver:CloseWindow",{}]
[task 2023-02-15T21:12:58.101Z] 21:12:58     INFO -  DEBUG: Adding blocker Interactions.jsm:: store for phase Places Clients shutdown
[task 2023-02-15T21:12:58.101Z] 21:12:58     INFO -  1676495578048	RemoteAgent	TRACE	Received DOM event TabClose for [object XULElement]
[task 2023-02-15T21:12:58.102Z] 21:12:58     INFO -  1676495578053	Marionette	TRACE	[12] MarionetteCommands actor destroyed for window id 4294967298
[task 2023-02-15T21:12:58.102Z] 21:12:58     INFO -  1676495578061	Marionette	TRACE	Received observer notification message-manager-disconnect
[task 2023-02-15T21:12:58.102Z] 21:12:58     INFO -  1676495578062	Marionette	TRACE	Received observer notification message-manager-disconnect
[task 2023-02-15T21:12:58.102Z] 21:12:58     INFO -  1676495578062	Marionette	DEBUG	1 <- [1,21,null,["328a4df7-e9ac-4ab2-a6a5-5c9ec75e2557"]]
[task 2023-02-15T21:12:58.103Z] 21:12:58     INFO -  1676495578081	Marionette	DEBUG	1 -> [0,22,"WebDriver:SwitchToWindow",{"handle":"328a4df7-e9ac-4ab2-a6a5-5c9ec75e2557","focus":true}]
[task 2023-02-15T21:12:58.103Z] 21:12:58     INFO -  1676495578081	Marionette	DEBUG	1 <- [1,22,null,{"value":null}]
[task 2023-02-15T21:12:58.104Z] 21:12:58     INFO -  DEBUG: Adding blocker ContentParent: id=12c2d4700 for phase xpcom-will-shutdown
[task 2023-02-15T21:12:58.104Z] 21:12:58     INFO -  DEBUG: Adding blocker ContentParent: id=12c2d4700 for phase profile-before-change
[task 2023-02-15T21:12:58.105Z] 21:12:58     INFO -  DEBUG: Adding blocker ContentParent: id=12c2d4700 for phase quit-application-granted
[task 2023-02-15T21:12:58.105Z] 21:12:58     INFO -  1676495578084	Marionette	DEBUG	1 -> [0,23,"Marionette:GetContext",{}]
[task 2023-02-15T21:12:58.105Z] 21:12:58     INFO -  1676495578084	Marionette	DEBUG	1 <- [1,23,null,{"value":"content"}]
[task 2023-02-15T21:12:58.105Z] 21:12:58     INFO -  1676495578086	Marionette	DEBUG	1 -> [0,24,"Marionette:SetContext",{"value":"chrome"}]
[task 2023-02-15T21:12:58.106Z] 21:12:58     INFO -  1676495578086	Marionette	DEBUG	1 <- [1,24,null,{"value":null}]
[task 2023-02-15T21:12:58.106Z] 21:12:58     INFO -  DEBUG: Adding blocker Transaction (4) for phase content-prefs.sqlite#0: waiting for clients
[task 2023-02-15T21:12:58.106Z] 21:12:58     INFO -  1676495578104	Marionette	DEBUG	1 -> [0,25,"WebDriver:GetWindowHandles",{}]
[task 2023-02-15T21:12:58.106Z] 21:12:58     INFO -  1676495578104	Marionette	DEBUG	1 <- [1,25,null,["17720d03-9f5b-46d3-97d5-7258e14a7b6f"]]
[task 2023-02-15T21:12:58.107Z] 21:12:58     INFO -  DEBUG: Adding blocker protections.sqlite#0: waiting for shutdown for phase Sqlite.sys.mjs: wait until all connections are closed
[task 2023-02-15T21:12:58.113Z] 21:12:58     INFO -  DEBUG: Adding blocker TrackingDBService: Shutting down the content blocking database. for phase profile-before-change
[task 2023-02-15T21:12:58.113Z] 21:12:58     INFO -  1676495578111	Marionette	DEBUG	1 -> [0,26,"Marionette:SetContext",{"value":"content"}]
[task 2023-02-15T21:12:58.113Z] 21:12:58     INFO -  1676495578111	Marionette	DEBUG	1 <- [1,26,null,{"value":null}]
[task 2023-02-15T21:12:58.113Z] 21:12:58     INFO -  DEBUG: Completed blocker Transaction (4) for phase content-prefs.sqlite#0: waiting for clients
<...>

@Sean, this is also a fallout from bug 1444491 as backfills and retriggers indicate

Flags: needinfo?(sefeng)
Regressed by: 1444491

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

Patch is made to fix this.

Flags: needinfo?(sefeng)

ah Sorry I cleared my NI in the wrong bug, but I am making a patch for this also

Need to call rAF to ensure autofocus candidates are flushed.

Assignee: nobody → sefeng
Status: NEW → ASSIGNED
Whiteboard: [retriggered]

Sefeng, given that different tests are failing more or less it might be good to move the patch to another Marionette specific bug.

I also wonder if such a change might require a WebDriver specification change. I'll discuss with James.

No longer blocks: 1816955
Summary: Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestNavigate.test_focus_after_navigation | marionette_driver.errors.NoSuchElementException: Unable to locate element: :focus → High frequency testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestNavigate.test_focus_after_navigation | marionette_driver.errors.NoSuchElementException: Unable to locate element: :focus
Pushed by sefeng@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/b5f7ded6b5cb Fix intermittent marionette/harness/marionette_harness/tests/unit/test_navigation.py r=emilio,webdriver-reviewers,whimboo
Status: ASSIGNED → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
Target Milestone: --- → 112 Branch
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: