Closed
Bug 1445212
Opened 7 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)
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
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Updated•7 years ago
|
Component: web-platform-tests → geckodriver
Comment 3•7 years ago
|
||
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
Comment 4•7 years ago
|
||
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.
Comment 5•7 years ago
|
||
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)
Comment 6•7 years ago
|
||
Comment hidden (Intermittent Failures Robot) |
Comment 8•7 years ago
|
||
(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).
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 11•7 years ago
|
||
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
Comment 13•7 years ago
|
||
Status: NEW → RESOLVED
Closed: 7 years ago
Resolution: --- → INCOMPLETE
Comment 14•7 years ago
|
||
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 → ---
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 27•6 years ago
|
||
Status: REOPENED → RESOLVED
Closed: 7 years ago → 6 years ago
Resolution: --- → INCOMPLETE
Comment 28•2 years ago
|
||
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.
Description
•