1515775 - Intermittent /webdriver/tests/maximize_window/maximize.py | test_fully_exit_fullscreen - AssertionError: timeout (500):

Status: RESOLVED FIXED

(Remote Protocol :: Marionette, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: nbeleuzu [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=218194900&repo=autoland

https://queue.taskcluster.net/v1/task/Bd5Ew-KyRe2N3Sk6-RGUww/runs/0/artifacts/public/logs/live_backing.log

12:02:21     INFO - TEST-PASS | /webdriver/tests/maximize_window/maximize.py | test_no_browsing_context 
12:02:21     INFO - TEST-UNEXPECTED-FAIL | /webdriver/tests/maximize_window/maximize.py | test_fully_exit_fullscreen - AssertionError: timeout (500):
12:02:21     INFO - session = <Session e3e09759-88c9-3044-a68a-fa1182605b18>
12:02:21     INFO - 
12:02:21     INFO -     def test_fully_exit_fullscreen(session):
12:02:21     INFO -         session.window.fullscreen()
12:02:21     INFO -         assert is_fullscreen(session)
12:02:21     INFO -     
12:02:21     INFO -         response = maximize(session)
12:02:21     INFO - >       assert_success(response)
12:02:21     INFO - 
12:02:21     INFO - response   = <Response status=500 error=<TimeoutException http_status=500>>
12:02:21     INFO - session    = <Session e3e09759-88c9-3044-a68a-fa1182605b18>
12:02:21     INFO - 
12:02:21     INFO - tests/web-platform/tests/webdriver/tests/maximize_window/maximize.py:20: 
12:02:21     INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
12:02:21     INFO - 
12:02:21     INFO - response = <Response status=500 error=<TimeoutException http_status=500>>
12:02:21     INFO - value = None
12:02:21     INFO - 
12:02:21     INFO -     def assert_success(response, value=None):
12:02:21     INFO -         """
12:02:21     INFO -         Verify that the provided webdriver.Response instance described
12:02:21     INFO -         a valid error response as defined by `dfn-send-an-error` and
12:02:21     INFO -         the provided error code.
12:02:21     INFO -     
12:02:21     INFO -         :param response: ``webdriver.Response`` instance.
12:02:21     INFO -         :param value: Expected value of the response body, if any.
12:02:21     INFO -         """
12:02:21     INFO - >       assert response.status == 200, str(response.error)
12:02:21     INFO - E       AssertionError: timeout (500): 
12:02:21     INFO - E         
12:02:21     INFO - E         Remote-end stacktrace:
12:02:21     INFO - E         
12:02:21     INFO - E         WebDriverError@chrome://marionette/content/error.js:179:5
12:02:21     INFO - E         TimeoutError@chrome://marionette/content/error.js:446:5
12:02:21     INFO - E         bail@chrome://marionette/content/sync.js:212:19
12:02:21     INFO - E         
12:02:21     INFO - E       assert 500 == 200
12:02:21     INFO - E        +  where 500 = <Response status=500 error=<TimeoutException http_status=500>>.status
12:02:21     INFO - 
12:02:21     INFO - response   = <Response status=500 error=<TimeoutException http_status=500>>
12:02:21     INFO - value      = None
12:02:21     INFO - 
12:02:21     INFO - tests/web-platform/tests/webdriver/tests/support/asserts.py:66: AssertionError
12:02:21     INFO - ....
12:02:21     INFO - TEST-OK | /webdriver/tests/maximize_window/maximize.py | took 15444ms

Comment 1

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

Problem here is in the `Maximize` command:

12:02:11     INFO - PID 2372 | 1545336131580	Marionette	DEBUG	0 -> [0,30,"WebDriver:MaximizeWindow",{}]
12:02:13     INFO - PID 2372 | 1545336133082	Marionette	DEBUG	0 <- [1,30,{"error":"timeout","message":"","stacktrace":"WebDriverError@chrome://marionette/content/error.js:179:5\nTimeoutError@chrome://marionette/content/error.js:446:5\nbail@chrome://marionette/content/sync.js:212:19\n"},null]
12:02:13     INFO - PID 2372 | 1545336133082	webdriver::server	DEBUG	<- 500 Internal Server Error {"value":{"error":"timeout","message":"","stacktrace":"WebDriverError@chrome://marionette/content/error.js:179:5\nTimeoutError@chrome://marionette/content/error.js:446:5\nbail@chrome://marionette/content/sync.js:212:19\n"}}

As such it depends on bug 1515867.

Comment 2

[Intermittent Failures Robot]

2 failures in 2648 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-inbound: 1
* autoland: 1

Platform breakdown:
* osx-10-10: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1515775&startday=2018-12-17&endday=2018-12-23&tree=all

Comment 3

[Intermittent Failures Robot]

1 failures in 1668 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* try: 1

Platform breakdown:
* macosx64-nightly: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1515775&startday=2018-12-31&endday=2019-01-06&tree=all

Comment 4

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

Actually this is first occurring for going into fullscreen:

07:29:01 INFO - PID 2436 | 1546702141730 Marionette DEBUG 0 -> [0,28,"WebDriver:FullscreenWindow",{}]
07:29:03 INFO - PID 2436 | 1546702143238 Marionette WARN TimedPromise timed out after 1500 ms: stacktrace:
07:29:03 INFO - PID 2436 | bail@chrome://marionette/content/sync.js:196:64
07:29:03 INFO - PID 2436 | 1546702143253 Marionette DEBUG 0 <- [1,28,null,{"x":0,"y":0,"width":1280,"height":1024}]
07:29:03 INFO - PID 2436 | 1546702143253 webdriver::server DEBUG <- 200 OK {"value":{"x":0,"y":0,"width":1280,"height":1024}}
07:29:03 INFO - PID 2436 | 1546702143254 webdriver::server DEBUG -> POST /session/f108229d-1236-1149-ba58-d8cc3e7250d4/execute/sync {"args": [], "script": "\n return !!(window.fullScreen || document.webkitIsFullScreen)\n "}
07:29:03 INFO - PID 2436 | 1546702143255 Marionette DEBUG 0 -> [0,29,"WebDriver:ExecuteScript",{"args":[],"script":"\n return !!(window.fullScreen || document.webkitIsFullScreen)\n "}]
07:29:03 INFO - PID 2436 | 1546702143258 Marionette DEBUG 0 <- [1,29,null,{"value":true}]
07:29:03 INFO - PID 2436 | 1546702143258 webdriver::server DEBUG <- 200 OK {"value":true}
07:29:03 INFO - PID 2436 | 1546702143259 webdriver::server DEBUG -> POST /session/f108229d-1236-1149-ba58-d8cc3e7250d4/window/maximize {}
07:29:03 INFO - PID 2436 | 1546702143260 Marionette DEBUG 0 -> [0,30,"WebDriver:MaximizeWindow",{}]
07:29:04 INFO - PID 2436 | 1546702144761 Marionette DEBUG 0 <- [1,30,{"error":"timeout","message":"","stacktrace":"WebDriverError@chrome://marionette/content/error.js:179:5\nTimeoutError@chrome://marionette/content/error.js:446:5\nbail@chrome://marionette/content/sync.js:193:19\n"},null]
07:29:04 INFO - PID 2436 | 1546702144761 webdriver::server DEBUG <- 500 Internal Server Error {"value":{"error":"timeout","message":"","stacktrace":"WebDriverError@chrome://marionette/content/error.js:179:5\nTimeoutError@chrome://marionette/content/error.js:446:5\nbail@chrome://marionette/content/sync.js:193:19\n"}}

The timeout in SetWindowRect is a follow-up failure, but shouldn't also happen.

Comment 5

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

With bug 1521527 fixed no timeout errors are raised anymore for fullscreen.

Comment 6

[BMO Automation]

Moving bug to Remote Protocol::Marionette component per bug 1815831.