1838681 - Intermittent TEST-UNEXPECTED-TIMEOUT | WD | expected OK with [1,143,null,{"value":null}] in "WebDriver:Back"

Status: RESOLVED DUPLICATE of bug 1791951

(Remote Protocol :: Marionette, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2023-06-15T16:04:29.238Z] 16:04:29     INFO - PID 10888 | 1686845069237	Marionette	DEBUG	0 -> [0,142,"WebDriver:Navigate",{"url":"http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Cp%3Efoo&mime=text%2Fhtml&charset=UTF-8"}]
[task 2023-06-15T16:04:29.249Z] 16:04:29     INFO - PID 10888 | 1686845069248	Marionette	TRACE	[22] Received event beforeunload for http://web-platform.test:8000/webdriver/tests/support/html/frames_no_bfcache.html
[task 2023-06-15T16:04:29.283Z] 16:04:29     INFO - PID 10888 | 1686845069281	Marionette	TRACE	[22] Received event pagehide for http://web-platform.test:8000/webdriver/tests/support/html/frames_no_bfcache.html
[task 2023-06-15T16:04:29.337Z] 16:04:29     INFO - PID 10888 | 1686845069335	Marionette	TRACE	[22] 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%3Cp%3Efoo&mime=text%2Fhtml&charset=UTF-8
[task 2023-06-15T16:04:29.341Z] 16:04:29     INFO - PID 10888 | 1686845069339	Marionette	TRACE	[22] 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%3Cp%3Efoo&mime=text%2Fhtml&charset=UTF-8
[task 2023-06-15T16:04:29.342Z] 16:04:29     INFO - PID 10888 | 1686845069340	Marionette	DEBUG	0 <- [1,142,null,{"value":null}]
[task 2023-06-15T16:04:29.358Z] 16:04:29     INFO - PID 10888 | 1686845069356	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2023-06-15T16:04:29.359Z] 16:04:29     INFO - PID 10888 | 1686845069357	webdriver::server	DEBUG	-> POST /session/37d41560-5363-48e0-83d9-9595c38b1c52/back {}
[task 2023-06-15T16:04:29.361Z] 16:04:29     INFO - PID 10888 | 1686845069361	Marionette	DEBUG	0 -> [0,143,"WebDriver:Back",{}]
[task 2023-06-15T16:04:29.367Z] 16:04:29     INFO - PID 10888 | 1686845069366	Marionette	TRACE	[22] 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%3Cp%3Efoo&mime=text%2Fhtml&charset=UTF-8
[task 2023-06-15T16:04:29.412Z] 16:04:29     INFO - PID 10888 | 1686845069411	Marionette	TRACE	Remoteness change detected. Set new top-level browsing context to 23
[task 2023-06-15T16:04:29.434Z] 16:04:29     INFO - PID 10888 | 1686845069432	Marionette	TRACE	[23] Received event beforeunload for about:blank
[task 2023-06-15T16:04:29.443Z] 16:04:29     INFO - PID 10888 | 1686845069442	Marionette	TRACE	[23] Received event pagehide for about:blank
[task 2023-06-15T16:04:29.642Z] 16:04:29     INFO - PID 10888 | 1686845069641	Marionette	TRACE	[23] Received event DOMContentLoaded for http://web-platform.test:8000/webdriver/tests/support/html/frames_no_bfcache.html
[task 2023-06-15T16:04:30.015Z] 16:04:30     INFO - PID 10888 | 1686845070014	Marionette	TRACE	[23] Received event pageshow for http://web-platform.test:8000/webdriver/tests/support/html/frames_no_bfcache.html
[task 2023-06-15T16:04:30.017Z] 16:04:30     INFO - PID 10888 | 1686845070016	Marionette	DEBUG	0 <- [1,143,null,{"value":null}]
[task 2023-06-15T16:04:30.037Z] 16:04:30     INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/classic/forward/forward.py | expected OK
[task 2023-06-15T16:04:30.037Z] 16:04:30     INFO - TEST-INFO took 80003ms

Comment 1

[Henrik Skupin [:whimboo][⌚️UTC+1]]

The problem here is that the test runs into a timeout after 25s because the startup of Firefox takes 12 on its own:
https://treeherder.mozilla.org/logviewer?job_id=419449175&repo=autoland&lineNumber=33931-34044

Given that here most of the time is spent in waiting for the initial application window I'm going to dupe to bug 1791951.