Closed Bug 1445212 Opened 6 years ago Closed 6 years ago

Intermittent /webdriver/tests/set_window_rect/set.py | test_restore_from_maximized - assert 800 == 400

Categories

(Remote Protocol :: Marionette, defect, P5)

Version 3
defect

Tracking

(Not tracked)

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure)

Filed by: apavel [at] mozilla.com

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

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

[task 2018-03-12T20:30:46.928Z] 20:30:46     INFO - PID 6910 | Headers { Connection: close
[task 2018-03-12T20:30:46.929Z] 20:30:46     INFO - PID 6910 | , Content-Type: application/json; charset=utf-8
[task 2018-03-12T20:30:46.929Z] 20:30:46     INFO - PID 6910 | , Cache-Control: no-cache
[task 2018-03-12T20:30:46.931Z] 20:30:46     INFO - PID 6910 | , Content-Length: 13
[task 2018-03-12T20:30:46.932Z] 20:30:46     INFO - PID 6910 | , Date: Mon, 12 Mar 2018 20:30:29 GMT
[task 2018-03-12T20:30:46.933Z] 20:30:46     INFO - PID 6910 | , }]
[task 2018-03-12T20:30:46.933Z] 20:30:46     INFO - PID 6910 | 1520886629088	hyper::server::response	DEBUG	write 13 bytes
[task 2018-03-12T20:30:46.935Z] 20:30:46     INFO - PID 6910 | 1520886629088	hyper::server::response	TRACE	ending
[task 2018-03-12T20:30:46.936Z] 20:30:46     INFO - PID 6910 | 1520886629088	hyper::server	DEBUG	keep_alive = false for 127.0.0.1:41090
[task 2018-03-12T20:30:46.936Z] 20:30:46     INFO - PID 6910 | 1520886629088	hyper::server	DEBUG	keep_alive loop ending for 127.0.0.1:41090
[task 2018-03-12T20:30:46.958Z] 20:30:46     INFO - 
[task 2018-03-12T20:30:46.959Z] 20:30:46     INFO - TEST-PASS | /webdriver/tests/set_window_rect.py | test_no_change[rect12] 
[task 2018-03-12T20:30:46.959Z] 20:30:46     INFO - TEST-PASS | /webdriver/tests/set_window_rect.py | test_no_change[rect13] 
[task 2018-03-12T20:30:46.959Z] 20:30:46     INFO - TEST-PASS | /webdriver/tests/set_window_rect.py | test_no_change[rect14] 
[task 2018-03-12T20:30:46.960Z] 20:30:46     INFO - TEST-PASS | /webdriver/tests/set_window_rect.py | test_no_change[rect15] 
[task 2018-03-12T20:30:46.960Z] 20:30:46     INFO - TEST-PASS | /webdriver/tests/set_window_rect.py | test_no_change[rect16] 
[task 2018-03-12T20:30:46.960Z] 20:30:46     INFO - TEST-PASS | /webdriver/tests/set_window_rect.py | test_no_change[rect17] 
[task 2018-03-12T20:30:46.960Z] 20:30:46     INFO - TEST-PASS | /webdriver/tests/set_window_rect.py | test_no_change[rect18] 
[task 2018-03-12T20:30:46.961Z] 20:30:46     INFO - TEST-PASS | /webdriver/tests/set_window_rect.py | test_no_change[rect19] 
[task 2018-03-12T20:30:46.961Z] 20:30:46     INFO - TEST-PASS | /webdriver/tests/set_window_rect.py | test_fully_exit_fullscreen 
[task 2018-03-12T20:30:46.961Z] 20:30:46     INFO - TEST-PASS | /webdriver/tests/set_window_rect.py | test_restore_from_minimized 
[task 2018-03-12T20:30:46.962Z] 20:30:46     INFO - TEST-UNEXPECTED-FAIL | /webdriver/tests/set_window_rect.py | test_restore_from_maximized 
[task 2018-03-12T20:30:46.962Z] 20:30:46     INFO - session = <webdriver.client.Session object at 0x7fa7eff3e450>
[task 2018-03-12T20:30:46.962Z] 20:30:46     INFO - 
[task 2018-03-12T20:30:46.962Z] 20:30:46     INFO -     def test_restore_from_maximized(session):
[task 2018-03-12T20:30:46.963Z] 20:30:46     INFO -         """
[task 2018-03-12T20:30:46.963Z] 20:30:46     INFO -         12. If the visibility state of the top-level browsing context's
[task 2018-03-12T20:30:46.963Z] 20:30:46     INFO -         active document is hidden, restore the window.
[task 2018-03-12T20:30:46.963Z] 20:30:46     INFO -     
[task 2018-03-12T20:30:46.964Z] 20:30:46     INFO -         [...]
[task 2018-03-12T20:30:46.964Z] 20:30:46     INFO -     
[task 2018-03-12T20:30:46.964Z] 20:30:46     INFO -         To restore the window, given an operating system level window with
[task 2018-03-12T20:30:46.965Z] 20:30:46     INFO -         an associated top-level browsing context, run implementation-specific
[task 2018-03-12T20:30:46.965Z] 20:30:46     INFO -         steps to restore or unhide the window to the visible screen. Do not
[task 2018-03-12T20:30:46.965Z] 20:30:46     INFO -         return from this operation until the visibility state of the top-level
[task 2018-03-12T20:30:46.965Z] 20:30:46     INFO -         browsing context's active document has reached the visible state,
[task 2018-03-12T20:30:46.966Z] 20:30:46     INFO -         or until the operation times out.
[task 2018-03-12T20:30:46.966Z] 20:30:46     INFO -         """
[task 2018-03-12T20:30:46.966Z] 20:30:46     INFO -     
[task 2018-03-12T20:30:46.966Z] 20:30:46     INFO -         original_size = session.window.size
[task 2018-03-12T20:30:46.967Z] 20:30:46     INFO -         session.window.maximize()
[task 2018-03-12T20:30:46.967Z] 20:30:46     INFO -         assert session.window.size != original_size
[task 2018-03-12T20:30:46.967Z] 20:30:46     INFO -     
[task 2018-03-12T20:30:46.968Z] 20:30:46     INFO -         response = set_window_rect(session, {"width": 400, "height": 400})
[task 2018-03-12T20:30:46.969Z] 20:30:46     INFO -         value = assert_success(response)
[task 2018-03-12T20:30:46.970Z] 20:30:46     INFO - >       assert value["width"] == 400
[task 2018-03-12T20:30:46.970Z] 20:30:46     INFO - E       assert 800 == 400
[task 2018-03-12T20:30:46.971Z] 20:30:46     INFO - 
[task 2018-03-12T20:30:46.971Z] 20:30:46     INFO - original_size = (800, 600)
[task 2018-03-12T20:30:46.972Z] 20:30:46     INFO - response   = <Responsetatus=200 body={"value": {"y": 450, "width": 800, "x": 100, "height": 600}}>
[task 2018-03-12T20:30:46.972Z] 20:30:46     INFO - session    = <webdriver.client.Session object at 0x7fa7eff3e450>
[task 2018-03-12T20:30:46.972Z] 20:30:46     INFO - value      = {'height': 600, 'width': 800, 'x': 100, 'y': 450}
[task 2018-03-12T20:30:46.972Z] 20:30:46     INFO - 
[task 2018-03-12T20:30:46.972Z] 20:30:46     INFO - tests/web-platform/tests/webdriver/tests/set_window_rect.py:353: AssertionError
Component: web-platform-tests → geckodriver
A width of 400px has been requested, but it didn't change and was kept at 800px. I have taken a look at the log and the output doesn't make sense at all:

https://treeherder.mozilla.org/logviewer.html#?job_id=171233020&repo=try&lineNumber=59785-59942

Even the test has a line `session.window.maximize()`, not a single POST request to `/session/{session id}/window/maximize` gets issued. Instead I see a POST request to `/session/{session id}/window/fullscreen`.

Also the fullscreen command caused the window to have a size of 800x600. Do we really run the tests on such a low resolution?
Flags: needinfo?(ato)
Summary: Intermittent /webdriver/tests/set_window_rect.py | test_restore_from_maximized → Intermittent /webdriver/tests/set_window_rect.py | test_restore_from_maximized - assert 800 == 400
I think the logging is broken and we cannot trust the lines when a test starts/ends. The related log for this test comes under the next one which is `test_height_width`:

https://treeherder.mozilla.org/logviewer.html#?job_id=171233020&repo=try&lineNumber=59987-60004

So we start with a 800x600 window, maximize to 1600x1200, and then trying to resize to 400x400. But the window size ends-up with 800x600, which is the original size, but not the one which has been requested.
It’s suspicious that the Marionette returns pretty much instantly
after receiving setWindowRect:

> [task 2018-03-30T17:52:42.208Z] 17:52:42     INFO - PID 6392 | 1522432361887	Marionette	TRACE	0 -> [0,686,"setWindowRect",{"height":400,"width":400,"x":null,"y":null}]
> [task 2018-03-30T17:52:42.209Z] 17:52:42     INFO - PID 6392 | 1522432361974	Marionette	TRACE	0 <- [1,686,null,{"x":100,"y":450,"width":800,"height":600,"state":"normal"}]

GeckoDriver#setWindowRect uses a PollPromise to wait for the window
size to change [1] but not for the window to reach its designated
size.  This is intentional because we can never guarantee the window
to reach the requested size.

It looks to me like 800x600 is an intermediary state from 1600x1200
before it reaches 400x400.  I don’t have any great ideas how to
make this synchronous given the primitives available to us.  Perhaps
a timed poll for the designated size that times out after N seconds.
Flags: needinfo?(ato)
(In reply to Andreas Tolfsen ‹:ato› from comment #5)
> It looks to me like 800x600 is an intermediary state from 1600x1200
> before it reaches 400x400.  I don’t have any great ideas how to
> make this synchronous given the primitives available to us.  Perhaps
> a timed poll for the designated size that times out after N seconds.

I see. So I think that this would be a good idea. We only have to make sure that if it fails we do not treat it as failure, and also maybe don't set the timeout value too high. Maybe 1s should be the maximum limit if we want to also take care of slower systems or slow running builds (ccov, valgrind).
The path to the test has been changed.
Summary: Intermittent /webdriver/tests/set_window_rect.py | test_restore_from_maximized - assert 800 == 400 → Intermittent /webdriver/tests/set_window_rect/set.py | test_restore_from_maximized - assert 800 == 400
Recent failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=187929570&repo=autoland&lineNumber=97483

[task 2018-07-12T23:35:00.989Z] 23:35:00     INFO - STDOUT: :250: AssertionError
[task 2018-07-12T23:35:00.989Z] 23:35:00     INFO - STDOUT: =============================== warnings summary ===============================
[task 2018-07-12T23:35:00.989Z] 23:35:00     INFO - STDOUT: <undetermined location>
[task 2018-07-12T23:35:00.989Z] 23:35:00     INFO - STDOUT:   Module already imported so cannot be rewritten: mozlog
[task 2018-07-12T23:35:00.989Z] 23:35:00     INFO - STDOUT: -- Docs: http://doc.pytest.org/en/latest/warnings.html
[task 2018-07-12T23:35:00.990Z] 23:35:00     INFO - STDOUT: =============== 1 failed, 68 passed, 1 warnings in 30.98 seconds ===============
[task 2018-07-12T23:35:01.010Z] 23:35:01     INFO - 
[task 2018-07-12T23:35:01.010Z] 23:35:01     INFO - TEST-PASS | /webdriver/tests/set_window_rect/set.py | test_no_change[rect12] 
[task 2018-07-12T23:35:01.011Z] 23:35:01     INFO - TEST-PASS | /webdriver/tests/set_window_rect/set.py | test_no_change[rect13] 
[task 2018-07-12T23:35:01.011Z] 23:35:01     INFO - TEST-PASS | /webdriver/tests/set_window_rect/set.py | test_no_change[rect14] 
[task 2018-07-12T23:35:01.012Z] 23:35:01     INFO - TEST-PASS | /webdriver/tests/set_window_rect/set.py | test_no_change[rect15] 
[task 2018-07-12T23:35:01.012Z] 23:35:01     INFO - TEST-PASS | /webdriver/tests/set_window_rect/set.py | test_no_change[rect16] 
[task 2018-07-12T23:35:01.012Z] 23:35:01     INFO - TEST-PASS | /webdriver/tests/set_window_rect/set.py | test_no_change[rect17] 
[task 2018-07-12T23:35:01.013Z] 23:35:01     INFO - TEST-PASS | /webdriver/tests/set_window_rect/set.py | test_no_change[rect18] 
[task 2018-07-12T23:35:01.013Z] 23:35:01     INFO - TEST-PASS | /webdriver/tests/set_window_rect/set.py | test_no_change[rect19] 
[task 2018-07-12T23:35:01.014Z] 23:35:01     INFO - TEST-PASS | /webdriver/tests/set_window_rect/set.py | test_fully_exit_fullscreen 
[task 2018-07-12T23:35:01.014Z] 23:35:01     INFO - TEST-PASS | /webdriver/tests/set_window_rect/set.py | test_restore_from_minimized 
[task 2018-07-12T23:35:01.015Z] 23:35:01     INFO - TEST-UNEXPECTED-FAIL | /webdriver/tests/set_window_rect/set.py | test_restore_from_maximized - assert 800 == 400
[task 2018-07-12T23:35:01.015Z] 23:35:01     INFO - session = <Session 5cb66617-8da0-4aa9-a671-0cb938593628>
[task 2018-07-12T23:35:01.016Z] 23:35:01     INFO - 
[task 2018-07-12T23:35:01.016Z] 23:35:01     INFO -     def test_restore_from_maximized(session):
[task 2018-07-12T23:35:01.016Z] 23:35:01     INFO -         """
[task 2018-07-12T23:35:01.016Z] 23:35:01     INFO -         12. If the visibility state of the top-level browsing context's
[task 2018-07-12T23:35:01.017Z] 23:35:01     INFO -         active document is hidden, restore the window.
[task 2018-07-12T23:35:01.017Z] 23:35:01     INFO -     
[task 2018-07-12T23:35:01.018Z] 23:35:01     INFO -         [...]
[task 2018-07-12T23:35:01.018Z] 23:35:01     INFO -     
[task 2018-07-12T23:35:01.019Z] 23:35:01     INFO -         To restore the window, given an operating system level window with
[task 2018-07-12T23:35:01.019Z] 23:35:01     INFO -         an associated top-level browsing context, run implementation-specific
[task 2018-07-12T23:35:01.019Z] 23:35:01     INFO -         steps to restore or unhide the window to the visible screen. Do not
[task 2018-07-12T23:35:01.019Z] 23:35:01     INFO -         return from this operation until the visibility state of the top-level
[task 2018-07-12T23:35:01.020Z] 23:35:01     INFO -         browsing context's active document has reached the visible state,
[task 2018-07-12T23:35:01.020Z] 23:35:01     INFO -         or until the operation times out.
[task 2018-07-12T23:35:01.021Z] 23:35:01     INFO -         """
[task 2018-07-12T23:35:01.021Z] 23:35:01     INFO -     
[task 2018-07-12T23:35:01.021Z] 23:35:01     INFO -         original_size = session.window.size
[task 2018-07-12T23:35:01.022Z] 23:35:01     INFO -         session.window.maximize()
[task 2018-07-12T23:35:01.023Z] 23:35:01     INFO -         assert session.window.size != original_size
[task 2018-07-12T23:35:01.024Z] 23:35:01     INFO -     
[task 2018-07-12T23:35:01.024Z] 23:35:01     INFO -         response = set_window_rect(session, {"width": 400, "height": 400})
[task 2018-07-12T23:35:01.025Z] 23:35:01     INFO -         value = assert_success(response)
[task 2018-07-12T23:35:01.026Z] 23:35:01     INFO - >       assert value["width"] == 400
[task 2018-07-12T23:35:01.026Z] 23:35:01     INFO - E       assert 800 == 400
[task 2018-07-12T23:35:01.027Z] 23:35:01     INFO - 
[task 2018-07-12T23:35:01.028Z] 23:35:01     INFO - original_size = (800, 600)
[task 2018-07-12T23:35:01.028Z] 23:35:01     INFO - response   = <Responsetatus=200 body={"value": {"y": 450, "width": 800, "x": 100, "height": 600}}>
[task 2018-07-12T23:35:01.028Z] 23:35:01     INFO - session    = <Session 5cb66617-8da0-4aa9-a671-0cb938593628>
[task 2018-07-12T23:35:01.029Z] 23:35:01     INFO - value      = {'height': 600, 'width': 800, 'x': 100, 'y': 450}
[task 2018-07-12T23:35:01.029Z] 23:35:01     INFO - 
[task 2018-07-12T23:35:01.029Z] 23:35:01     INFO - tests/web-platform/tests/webdriver/tests/set_window_rect/set.py:250: AssertionError
[task 2018-07-12T23:35:01.031Z] 23:35:01     INFO - ............
[task 2018-07-12T23:35:01.031Z] 23:35:01     INFO - TEST-OK | /webdriver/tests/set_window_rect/set.py | took 31214ms
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Depends on: 1492499
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
Status: REOPENED → RESOLVED
Closed: 6 years ago6 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.