1514616 - Intermittent /webdriver/tests/set_window_rect/set.py | test_fully_exit_fullscreen - AssertionError: timeout (500):

Status: RESOLVED FIXED

(Remote Protocol :: Marionette, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: dvarga [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=217318105&repo=mozilla-inbound

https://queue.taskcluster.net/v1/task/aAujDfpBQNOfQNc-0Bk6lA/runs/0/artifacts/public/logs/live_backing.log

11:50:50     INFO - TEST-PASS | /webdriver/tests/set_window_rect/set.py | test_no_change[rect16] 
11:50:50     INFO - TEST-PASS | /webdriver/tests/set_window_rect/set.py | test_no_change[rect17] 
11:50:50     INFO - TEST-PASS | /webdriver/tests/set_window_rect/set.py | test_no_change[rect18] 
11:50:50     INFO - TEST-PASS | /webdriver/tests/set_window_rect/set.py | test_no_change[rect19] 
11:50:50     INFO - TEST-UNEXPECTED-FAIL | /webdriver/tests/set_window_rect/set.py | test_fully_exit_fullscreen - AssertionError: timeout (500):
11:50:50     INFO - session = <Session f95cb93a-8956-414b-9d5c-004b0dd508c5>
11:50:50     INFO - 
11:50:50     INFO -     def test_fully_exit_fullscreen(session):
11:50:50     INFO -         session.window.fullscreen()
11:50:50     INFO -         assert is_fullscreen(session)
11:50:50     INFO -     
11:50:50     INFO -         response = set_window_rect(session, {"width": 400, "height": 400})
11:50:50     INFO - >       value = assert_success(response)
11:50:50     INFO - 
11:50:50     INFO - response   = <Response status=500 error=<TimeoutException http_status=500>>
11:50:50     INFO - session    = <Session f95cb93a-8956-414b-9d5c-004b0dd508c5>
11:50:50     INFO - 
11:50:50     INFO - tests/web-platform/tests/webdriver/tests/set_window_rect/set.py:139: 
11:50:50     INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
11:50:50     INFO - 
11:50:50     INFO - response = <Response status=500 error=<TimeoutException http_status=500>>
11:50:50     INFO - value = None
11:50:50     INFO - 
11:50:50     INFO -     def assert_success(response, value=None):
11:50:50     INFO -         """
11:50:50     INFO -         Verify that the provided webdriver.Response instance described
11:50:50     INFO -         a valid error response as defined by `dfn-send-an-error` and
11:50:50     INFO -         the provided error code.
11:50:50     INFO -     
11:50:50     INFO -         :param response: ``webdriver.Response`` instance.
11:50:50     INFO -         :param value: Expected value of the response body, if any.
11:50:50     INFO -         """
11:50:50     INFO - >       assert response.status == 200, str(response.error)
11:50:50     INFO - E       AssertionError: timeout (500):

Comment 1

[Intermittent Failures Robot]

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

Repository breakdown:
* mozilla-inbound: 1

Platform breakdown:
* osx-10-10: 1

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

Comment 2

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

This is caused by a hang in SetWindowRect, and as such dependent on bug 1489955:

11:50:36     INFO - PID 1237 | 1544989836282	Marionette	DEBUG	0 -> [0,884,"WebDriver:SetWindowRect",{"height":400,"width":400}]
11:50:37     INFO - PID 1237 | 1544989837784	Marionette	DEBUG	0 <- [1,884,{"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]
11:50:37     INFO - PID 1237 | 1544989837784	webdriver::server	DEBUG	<- 500 Internal Server Error {"value":

Comment 3

[Intermittent Failures Robot]

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

Repository breakdown:
* autoland: 1

Platform breakdown:
* osx-10-10: 1

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

Comment 4

[Intermittent Failures Robot]

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

Repository breakdown:
* autoland: 1

Platform breakdown:
* osx-10-10: 1

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

Comment 5

[Intermittent Failures Robot]

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

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

Platform breakdown:
* osx-10-10: 2

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

Comment 6

[Intermittent Failures Robot]

5 failures in 2627 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1
• mozilla-inbound: 1
• mozilla-central: 1
• mozilla-beta: 2

Platform breakdown:

• osx-10-10: 2
• macosx64-nightly: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1514616&startday=2019-01-07&endday=2019-01-13&tree=all

Comment 7

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

Actually this is first occurring for going into fullscreen:

15:13:39 INFO - PID 1236 | 1547334819385 Marionette DEBUG 0 -> [0,882,"WebDriver:FullscreenWindow",{}]
15:13:40 INFO - PID 1236 | 1547334820886 Marionette WARN TimedPromise timed out after 1500 ms: stacktrace:
15:13:40 INFO - PID 1236 | bail@chrome://marionette/content/sync.js:196:64
15:13:40 INFO - PID 1236 | 1547334820902 Marionette DEBUG 0 <- [1,882,null,{"x":0,"y":0,"width":1280,"height":1024,"state":"fullscreen"}]
15:13:40 INFO - PID 1236 | 1547334820902 webdriver::server DEBUG <- 200 OK {"value":{"x":0,"y":0,"width":1280,"height":1024}}
15:13:40 INFO - PID 1236 | 1547334820904 webdriver::server DEBUG -> POST /session/9cf382cd-32db-af4d-9689-3757ba5671f7/execute/sync {"args": [], "script": "\n return !!(window.fullScreen || document.webkitIsFullScreen)\n "}
15:13:40 INFO - PID 1236 | 1547334820906 Marionette DEBUG 0 -> [0,883,"WebDriver:ExecuteScript",{"args":[],"script":"\n return !!(window.fullScreen || document.webkitIsFullScreen)\n "}]
15:13:40 INFO - PID 1236 | 1547334820911 Marionette DEBUG 0 <- [1,883,null,{"value":true}]
15:13:40 INFO - PID 1236 | 1547334820911 webdriver::server DEBUG <- 200 OK {"value":true}
15:13:40 INFO - PID 1236 | 1547334820913 webdriver::server DEBUG -> POST /session/9cf382cd-32db-af4d-9689-3757ba5671f7/window/rect {"width": 400, "height": 400}
15:13:40 INFO - PID 1236 | 1547334820915 Marionette DEBUG 0 -> [0,884,"WebDriver:SetWindowRect",{"height":400,"width":400}]
15:13:42 INFO - PID 1236 | 1547334822418 Marionette DEBUG 0 <- [1,884,{"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]
15:13:42 INFO - PID 1236 | 1547334822418 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 8

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

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

Comment 9

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-beta: 1

Platform breakdown:

• macosx64-devedition: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1514616&startday=2019-01-21&endday=2019-01-27&tree=all

Comment 10

[BMO Automation]

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