Closed Bug 1780630 Opened 3 years ago Closed 3 years ago

Intermittent Wd TEST-UNEXPECTED-TIMEOUT | expected OK (backing up preferences takes a long time)

Categories

(Remote Protocol :: Marionette, defect, P5)

Product:
Remote Protocol
Component:
Marionette
Type:
defect

Tracking

(Not tracked)

Status:
RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure)

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

[task 2022-07-21T17:59:27.420Z] 17:59:27     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/get_computed_label/get.py::test_stale_element_reference[child_context] 
[task 2022-07-21T17:59:27.421Z] 17:59:27     INFO - PID 5560 | 1658426367413	webdriver::server	DEBUG	-> POST /session/c3e96750-292e-4105-a5b0-b46c6236f649/window/rect {"width": 800, "height": 600}
[task 2022-07-21T17:59:27.422Z] 17:59:27     INFO - PID 5560 | 1658426367414	Marionette	DEBUG	0 -> [0,50,"WebDriver:SetWindowRect",{"height":600,"width":800}]
[task 2022-07-21T17:59:27.422Z] 17:59:27     INFO - PID 5560 | 1658426367418	Marionette	TRACE	Requested window geometry matches
[task 2022-07-21T17:59:27.423Z] 17:59:27     INFO - PID 5560 | 1658426367419	Marionette	DEBUG	0 <- [1,50,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2022-07-21T17:59:27.424Z] 17:59:27     INFO - PID 5560 | 1658426367419	webdriver::server	DEBUG	<- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2022-07-21T17:59:27.424Z] 17:59:27     INFO - PID 5560 | 1658426367420	webdriver::server	DEBUG	-> POST /session/c3e96750-292e-4105-a5b0-b46c6236f649/window/rect {"x": 100, "y": 100}
[task 2022-07-21T17:59:27.425Z] 17:59:27     INFO - PID 5560 | 1658426367420	Marionette	DEBUG	0 -> [0,51,"WebDriver:SetWindowRect",{"x":100,"y":100}]
[task 2022-07-21T17:59:27.426Z] 17:59:27     INFO - PID 5560 | 1658426367421	Marionette	TRACE	Requested window geometry matches
[task 2022-07-21T17:59:27.426Z] 17:59:27     INFO - PID 5560 | 1658426367421	Marionette	DEBUG	0 <- [1,51,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2022-07-21T17:59:27.427Z] 17:59:27     INFO - PID 5560 | 1658426367421	webdriver::server	DEBUG	<- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2022-07-21T17:59:27.428Z] 17:59:27     INFO - PID 5560 | 1658426367423	webdriver::server	DEBUG	-> POST /session/c3e96750-292e-4105-a5b0-b46c6236f649/url {"url": "http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Ciframe+src%3D%27http%3A%2F%2Fweb-platform.test%3A8000%2Fwebdriver%2Ftests%2Fsupport%2Finline.py%3Fdoc%3D%253C%2521doctype%2Bhtml%253E%250A%253Cmeta%2Bcharset%253DUTF-8%253E%250A%253Cinput%253E%26mime%3Dtext%252Fhtml%26charset%3DUTF-8%27%3E%3C%2Fiframe%3E&mime=text%2Fhtml&charset=UTF-8"}
[task 2022-07-21T17:59:27.429Z] 17:59:27     INFO - PID 5560 | 1658426367423	Marionette	DEBUG	0 -> [0,52,"WebDriver:Navigate",{"url":"http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E% ... TF-8%253E%250A%253Cinput%253E%26mime%3Dtext%252Fhtml%26charset%3DUTF-8%27%3E%3C%2Fiframe%3E&mime=text%2Fhtml&charset=UTF-8"}]
[task 2022-07-21T17:59:27.429Z] 17:59:27     INFO - PID 5560 | 1658426367426	Marionette	TRACE	[43] Received event beforeunload for http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Cinput%3E&mime=text%2Fhtml&charset=UTF-8
[task 2022-07-21T17:59:27.438Z] 17:59:27     INFO - PID 5560 | 1658426367437	Marionette	TRACE	Remoteness change detected. Set new top-level browsing context to 45
[task 2022-07-21T17:59:27.443Z] 17:59:27     INFO - PID 5560 | 1658426367442	Marionette	TRACE	[45] Received event beforeunload for about:blank
[task 2022-07-21T17:59:27.446Z] 17:59:27     INFO - PID 5560 | 1658426367445	Marionette	TRACE	[45] Received event pagehide for about:blank
[task 2022-07-21T17:59:27.460Z] 17:59:27     INFO - PID 5560 | 1658426367464	Marionette	TRACE	[45] Received event DOMContentLoaded for http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Ci ... 3DUTF-8%253E%250A%253Cinput%253E%26mime%3Dtext%252Fhtml%26charset%3DUTF-8%27%3E%3C%2Fiframe%3E&mime=text%2Fhtml&charset=UTF-8
[task 2022-07-21T17:59:27.478Z] 17:59:27     INFO - PID 5560 | 1658426367476	Marionette	TRACE	[45] Received event pageshow for http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Ci ... 3DUTF-8%253E%250A%253Cinput%253E%26mime%3Dtext%252Fhtml%26charset%3DUTF-8%27%3E%3C%2Fiframe%3E&mime=text%2Fhtml&charset=UTF-8
[task 2022-07-21T17:59:27.478Z] 17:59:27     INFO - PID 5560 | 1658426367477	Marionette	DEBUG	0 <- [1,52,null,{"value":null}]
[task 2022-07-21T17:59:27.480Z] 17:59:27     INFO - PID 5560 | 1658426367480	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-07-21T17:59:27.481Z] 17:59:27     INFO - PID 5560 | 1658426367481	webdriver::server	DEBUG	-> POST /session/c3e96750-292e-4105-a5b0-b46c6236f649/element {"using": "css selector", "value": "iframe"}
[task 2022-07-21T17:59:27.482Z] 17:59:27     INFO - PID 5560 | 1658426367481	Marionette	DEBUG	0 -> [0,53,"WebDriver:FindElement",{"using":"css selector","value":"iframe"}]
[task 2022-07-21T17:59:27.483Z] 17:59:27     INFO - PID 5560 | 1658426367482	Marionette	TRACE	[45] MarionetteCommands actor created for window id 10737418242
[task 2022-07-21T17:59:27.485Z] 17:59:27     INFO - PID 5560 | 1658426367484	Marionette	DEBUG	0 <- [1,53,null,{"value":{"element-6066-11e4-a52e-4f735466cecf":"b56c2618-5c32-4f47-aab7-1168f3f2086a"}}]
[task 2022-07-21T17:59:27.485Z] 17:59:27     INFO - PID 5560 | 1658426367484	webdriver::server	DEBUG	<- 200 OK {"value":{"element-6066-11e4-a52e-4f735466cecf":"b56c2618-5c32-4f47-aab7-1168f3f2086a"}}
[task 2022-07-21T17:59:27.486Z] 17:59:27     INFO - PID 5560 | 1658426367485	webdriver::server	DEBUG	-> POST /session/c3e96750-292e-4105-a5b0-b46c6236f649/frame {"id": {"element-6066-11e4-a52e-4f735466cecf": "b56c2618-5c32-4f47-aab7-1168f3f2086a"}}
[task 2022-07-21T17:59:27.487Z] 17:59:27     INFO - PID 5560 | 1658426367486	Marionette	DEBUG	0 -> [0,54,"WebDriver:SwitchToFrame",{"element":"b56c2618-5c32-4f47-aab7-1168f3f2086a"}]
[task 2022-07-21T17:59:27.488Z] 17:59:27     INFO - PID 5560 | 1658426367487	Marionette	DEBUG	0 <- [1,54,null,{"value":null}]
[task 2022-07-21T17:59:27.489Z] 17:59:27     INFO - PID 5560 | 1658426367488	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-07-21T17:59:27.489Z] 17:59:27     INFO - PID 5560 | 1658426367489	webdriver::server	DEBUG	-> POST /session/c3e96750-292e-4105-a5b0-b46c6236f649/element {"using": "css selector", "value": "input"}
[task 2022-07-21T17:59:27.493Z] 17:59:27     INFO - PID 5560 | 1658426367493	Marionette	DEBUG	0 -> [0,55,"WebDriver:FindElement",{"using":"css selector","value":"input"}]
[task 2022-07-21T17:59:27.494Z] 17:59:27     INFO - PID 5560 | 1658426367494	Marionette	TRACE	[10737418241] MarionetteCommands actor created for window id 10737418244
[task 2022-07-21T17:59:27.497Z] 17:59:27     INFO - PID 5560 | 1658426367496	Marionette	DEBUG	0 <- [1,55,null,{"value":{"element-6066-11e4-a52e-4f735466cecf":"0466ff20-4e96-4e5a-8627-40a887381f75"}}]
[task 2022-07-21T17:59:27.498Z] 17:59:27     INFO - PID 5560 | 1658426367497	webdriver::server	DEBUG	<- 200 OK {"value":{"element-6066-11e4-a52e-4f735466cecf":"0466ff20-4e96-4e5a-8627-40a887381f75"}}
[task 2022-07-21T17:59:27.498Z] 17:59:27     INFO - PID 5560 | 1658426367498	webdriver::server	DEBUG	-> POST /session/c3e96750-292e-4105-a5b0-b46c6236f649/execute/sync {"script": "arguments[0].remove();", "args": [{"element-6066-11e4-a52e-4f735466cecf": "0466ff20-4e96-4e5a-8627-40a887381f75"}]}
[task 2022-07-21T17:59:27.499Z] 17:59:27     INFO - PID 5560 | 1658426367498	Marionette	DEBUG	0 -> [0,56,"WebDriver:ExecuteScript",{"args":[{"element-6066-11e4-a52e-4f735466cecf":"0466ff20-4e96-4e5a-8627-40a887381f75"}],"script":"arguments[0].remove();"}]
[task 2022-07-21T17:59:27.502Z] 17:59:27     INFO - PID 5560 | 1658426367502	Marionette	DEBUG	0 <- [1,56,null,{"value":null}]
[task 2022-07-21T17:59:27.503Z] 17:59:27     INFO - PID 5560 | 1658426367502	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-07-21T17:59:27.506Z] 17:59:27     INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/get_computed_label/get.py | expected OK
[task 2022-07-21T17:59:27.506Z] 17:59:27     INFO - TEST-INFO took 55029ms
[task 2022-07-21T17:59:27.507Z] 17:59:27     INFO - Restarting browser for new test group
[task 2022-07-21T17:59:29.587Z] 17:59:29     INFO - Closing logging queue
[task 2022-07-21T17:59:29.590Z] 17:59:29     INFO - queue closed
[task 2022-07-21T17:59:30.102Z] 17:59:30     INFO - PID 7044 | 1658426369601	geckodriver	INFO	Listening on 127.0.0.1:49877
[task 2022-07-21T17:59:30.103Z] 17:59:30     INFO - Starting runner
[task 2022-07-21T17:59:30.616Z] 17:59:30     INFO - TEST-START | /webdriver/tests/get_element_css_value/get.py

Backing up the preferences file took up nearly 1 minute!

https://treeherder.mozilla.org/logviewer?job_id=385032541&repo=mozilla-central&lineNumber=29894-29895

[task 2022-07-21T17:58:32.811Z] 17:58:32     INFO - PID 5560 | 1658426312810	geckodriver::browser	DEBUG	Backing up prefs to "C:\\Users\\task_165842530828862\\AppData\\Local\\Temp\\tmpk103s12a.mozrunner\\user.geckodriver_backup"
[task 2022-07-21T17:59:25.063Z] 17:59:25     INFO - PID 5560 | 1658426365075	mozrunner::runner	INFO	Running command: "Z:\\task_165842530828862\\build\\application\\firefox\\firefox.exe" "--marionette" "--profile" "C:\\Users\\task_165842530828862\\AppData\\Local\\Temp\\tmpk103s12a.mozrunner" "-no-remote"

Maybe due to bug 1757721 we accommodate a really large number of files?

Depends on: 1757721
Summary: Intermittent TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/get_computed_label/get.py | expected OK → Intermittent Wd TEST-UNEXPECTED-TIMEOUT | expected OK (backing up preferences takes a long time)

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → INCOMPLETE
Moving bug to Remote Protocol::Marionette component per bug 1815831.
Component: geckodriver → Marionette
Product: Testing → Remote Protocol
You need to log in before you can comment on or make changes to this bug.