1506894 - Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_window_rect.py TestWindowRect.test_set_position_and_size | AssertionError: 0 != 10

Status: RESOLVED FIXED

(Testing :: Marionette Client and Harness, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: nerli [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=211425526&repo=try

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

[task 2018-11-13T14:02:56.173Z] 14:02:56     INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_window_rect.py TestWindowRect.test_set_position_and_size
[task 2018-11-13T14:02:56.175Z] 14:02:56     INFO -  1542117776164	Marionette	TRACE	105 <- [1,13,null,{"value":null}]
[task 2018-11-13T14:02:56.178Z] 14:02:56     INFO -  1542117776168	Marionette	DEBUG	Closed connection 105
[task 2018-11-13T14:02:56.179Z] 14:02:56     INFO -  1542117776173	Marionette	DEBUG	Accepted connection 106 from 127.0.0.1:38548
[task 2018-11-13T14:02:56.182Z] 14:02:56     INFO -  1542117776178	Marionette	TRACE	106 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2018-11-13T14:02:56.240Z] 14:02:56     INFO -  1542117776231	Marionette	DEBUG	[2147483905] Frame script loaded
[task 2018-11-13T14:02:56.241Z] 14:02:56     INFO -  1542117776233	Marionette	DEBUG	[2147483905] Frame script registered
[task 2018-11-13T14:02:56.242Z] 14:02:56     INFO -  --DOMWINDOW == 51 (0xdddd5000) [pid = 2473] [serial = 248] [outer = (nil)] [url = about:blank]
[task 2018-11-13T14:02:56.243Z] 14:02:56     INFO -  --DOMWINDOW == 50 (0xdfdcbc00) [pid = 2473] [serial = 232] [outer = (nil)] [url = about:blank]
[task 2018-11-13T14:02:56.244Z] 14:02:56     INFO -  --DOMWINDOW == 49 (0xe04bd800) [pid = 2473] [serial = 230] [outer = (nil)] [url = about:blank]
[task 2018-11-13T14:02:56.245Z] 14:02:56     INFO -  --DOMWINDOW == 48 (0xdfad4400) [pid = 2473] [serial = 246] [outer = (nil)] [url = chrome://marionette/content/test2.xul]
[task 2018-11-13T14:02:56.246Z] 14:02:56     INFO -  --DOMWINDOW == 47 (0xe149b400) [pid = 2473] [serial = 244] [outer = (nil)] [url = chrome://marionette/content/test2.xul]
[task 2018-11-13T14:02:56.247Z] 14:02:56     INFO -  --DOMWINDOW == 46 (0xdddd8c00) [pid = 2473] [serial = 240] [outer = (nil)] [url = about:blank]
[task 2018-11-13T14:02:56.255Z] 14:02:56     INFO -  1542117776248	Marionette	TRACE	106 <- [1,1,null,{"sessionId":"9fd6f3a7-f274-4d20-bf81-fd3c8d28103d","capabilities":{"browserName":"firefox","browserVersion":"65.0" ... mp/tmpWHUOin.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2018-11-13T14:02:56.256Z] 14:02:56     INFO -  --DOMWINDOW == 45 (0xdfdc8400) [pid = 2473] [serial = 228] [outer = (nil)] [url = about:blank]
[task 2018-11-13T14:02:56.257Z] 14:02:56     INFO -  --DOMWINDOW == 44 (0xe310d000) [pid = 2473] [serial = 235] [outer = (nil)] [url = about:blank]
[task 2018-11-13T14:02:56.257Z] 14:02:56     INFO -  --DOMWINDOW == 43 (0xe3052800) [pid = 2473] [serial = 251] [outer = (nil)] [url = about:blank]
[task 2018-11-13T14:02:56.262Z] 14:02:56     INFO -  1542117776259	Marionette	TRACE	106 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2018-11-13T14:02:56.263Z] 14:02:56     INFO -  1542117776260	Marionette	TRACE	106 <- [1,2,null,{"value":null}]
[task 2018-11-13T14:02:56.265Z] 14:02:56     INFO -  1542117776264	Marionette	TRACE	106 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2018-11-13T14:02:56.269Z] 14:02:56     INFO -  1542117776266	Marionette	TRACE	106 <- [1,3,null,{"value":null}]
[task 2018-11-13T14:02:56.270Z] 14:02:56     INFO -  1542117776269	Marionette	TRACE	106 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2018-11-13T14:02:56.274Z] 14:02:56     INFO -  1542117776272	Marionette	TRACE	106 <- [1,4,null,{"value":null}]
[task 2018-11-13T14:02:56.279Z] 14:02:56     INFO -  1542117776274	Marionette	TRACE	106 -> [0,5,"WebDriver:GetWindowRect",{}]
[task 2018-11-13T14:02:56.283Z] 14:02:56     INFO -  1542117776278	Marionette	TRACE	106 <- [1,5,null,{"x":0,"y":0,"width":1280,"height":1040,"state":"normal"}]
[task 2018-11-13T14:02:56.284Z] 14:02:56     INFO -  1542117776282	Marionette	TRACE	106 -> [0,6,"WebDriver:ExecuteScript",{"scriptTimeout":null,"newSandbox":true,"args":[],"filename":"tests/testing/marionette/harness ... width: window.screen.availWidth,\n              height: window.screen.availHeight,\n            }","sandbox":null,"line":22}]
[task 2018-11-13T14:02:56.306Z] 14:02:56     INFO -  1542117776292	Marionette	TRACE	106 <- [1,6,null,{"value":{"width":1600,"height":1200}}]
[task 2018-11-13T14:02:56.307Z] 14:02:56     INFO -  1542117776294	Marionette	TRACE	106 -> [0,7,"WebDriver:SetWindowRect",{"y":null,"x":null,"width":1280,"height":1040}]
[task 2018-11-13T14:02:56.308Z] 14:02:56     INFO -  1542117776299	Marionette	TRACE	106 <- [1,7,null,{"x":0,"y":0,"width":1280,"height":1040,"state":"normal"}]
[task 2018-11-13T14:02:56.309Z] 14:02:56     INFO -  1542117776301	Marionette	TRACE	106 -> [0,8,"WebDriver:GetWindowRect",{}]
[task 2018-11-13T14:02:56.311Z] 14:02:56     INFO -  1542117776304	Marionette	TRACE	106 <- [1,8,null,{"x":0,"y":0,"width":1280,"height":1040,"state":"normal"}]
[task 2018-11-13T14:02:56.313Z] 14:02:56     INFO -  1542117776308	Marionette	TRACE	106 -> [0,9,"WebDriver:SetWindowRect",{"y":10,"x":10,"width":1230,"height":990}]
[task 2018-11-13T14:02:56.373Z] 14:02:56     INFO -  --DOMWINDOW == 42 (0xe3102800) [pid = 2473] [serial = 253] [outer = (nil)] [url = about:blank]
[task 2018-11-13T14:02:56.374Z] 14:02:56     INFO -  --DOMWINDOW == 41 (0xe3105000) [pid = 2473] [serial = 254] [outer = (nil)] [url = about:blank]
[task 2018-11-13T14:02:56.375Z] 14:02:56     INFO -  --DOMWINDOW == 40 (0xdf916c00) [pid = 2473] [serial = 245] [outer = (nil)] [url = chrome://marionette/content/test_nested_iframe.xul]
[task 2018-11-13T14:02:56.377Z] 14:02:56     INFO -  --DOMWINDOW == 39 (0xe31a3800) [pid = 2473] [serial = 237] [outer = (nil)] [url = about:blank]
[task 2018-11-13T14:02:56.378Z] 14:02:56     INFO -  --DOMWINDOW == 38 (0xe31aa800) [pid = 2473] [serial = 238] [outer = (nil)] [url = about:blank]
[task 2018-11-13T14:02:56.581Z] 14:02:56     INFO -  1542117776577	Marionette	TRACE	106 <- [1,9,null,{"x":0,"y":0,"width":1230,"height":990,"state":"normal"}]
[task 2018-11-13T14:02:56.590Z] 14:02:56     INFO -  1542117776584	Marionette	TRACE	106 -> [0,10,"WebDriver:GetWindowRect",{}]
[task 2018-11-13T14:02:56.591Z] 14:02:56     INFO -  1542117776587	Marionette	TRACE	106 <- [1,10,null,{"x":10,"y":10,"width":1230,"height":990,"state":"normal"}]
[task 2018-11-13T14:02:56.594Z] 14:02:56     INFO -  1542117776590	Marionette	TRACE	106 -> [0,11,"Marionette:GetContext",{}]
[task 2018-11-13T14:02:56.594Z] 14:02:56     INFO -  1542117776592	Marionette	TRACE	106 <- [1,11,null,{"value":"content"}]
[task 2018-11-13T14:02:56.602Z] 14:02:56     INFO -  1542117776597	Marionette	TRACE	106 -> [0,12,"Marionette:SetContext",{"value":"chrome"}]
[task 2018-11-13T14:02:56.603Z] 14:02:56     INFO -  1542117776598	Marionette	TRACE	106 <- [1,12,null,{"value":null}]
[task 2018-11-13T14:02:56.603Z] 14:02:56     INFO -  1542117776600	Marionette	TRACE	106 -> [0,13,"WebDriver:TakeScreenshot",{"highlights":null,"full":true,"hash":false,"id":null,"scroll":true}]
[task 2018-11-13T14:02:56.620Z] 14:02:56     INFO -  [Parent 2473, Main Thread] WARNING: Remote iframe not rendered: file /builds/worker/workspace/build/src/layout/ipc/RenderFrame.cpp, line 297
[task 2018-11-13T14:02:56.667Z] 14:02:56     INFO -  1542117776666	Marionette	TRACE	106 <- [1,13,null,{"value":"iVBORw0KGgoAAAANSUhEUgAABM4AAAPeCAYAAAD0+FZAAAAgAElEQVR4nOzd729U953ocR6u1P+jEqut1Kqr3Eit1F2ttA+iSLvNg6aq ... AAAEOcAQAAAMAQZwAAAAAwxBkAAAAADHEGAAAAAEOcAQAAAMAQZwAAAAAwxBkAAAAADHEGAAAAAEOcAQAAAMAQZwAAAAAwAg79sJDZU67PAAAAAElFTkSuQmCC"}]
[task 2018-11-13T14:02:56.677Z] 14:02:56     INFO -  1542117776671	Marionette	TRACE	106 -> [0,14,"Marionette:SetContext",{"value":"content"}]
[task 2018-11-13T14:02:56.679Z] 14:02:56     INFO -  1542117776672	Marionette	TRACE	106 <- [1,14,null,{"value":null}]
[task 2018-11-13T14:02:56.680Z] 14:02:56     INFO -  1542117776674	Marionette	TRACE	106 -> [0,15,"Marionette:GetContext",{}]
[task 2018-11-13T14:02:56.681Z] 14:02:56     INFO -  1542117776675	Marionette	TRACE	106 <- [1,15,null,{"value":"content"}]
[task 2018-11-13T14:02:56.684Z] 14:02:56     INFO -  1542117776678	Marionette	TRACE	106 -> [0,16,"Marionette:SetContext",{"value":"content"}]
[task 2018-11-13T14:02:56.685Z] 14:02:56     INFO -  1542117776681	Marionette	TRACE	106 <- [1,16,null,{"value":null}]
[task 2018-11-13T14:02:56.689Z] 14:02:56     INFO -  1542117776684	Marionette	TRACE	106 -> [0,17,"WebDriver:GetPageSource",{}]
[task 2018-11-13T14:02:56.692Z] 14:02:56     INFO -  1542117776691	Marionette	TRACE	106 <- [1,17,null,{"value":"<html><head>\n<title>Marionette New Tab Link</title>\n</head>\n<body>\n  <a href=\"empty.html\" id=\"new ... javascript:window.open(&quot;empty.html&quot;, null, &quot;location=1,toolbar=1&quot;);\">New Window</a>\n\n</body></html>"}]
[task 2018-11-13T14:02:56.699Z] 14:02:56     INFO -  1542117776694	Marionette	TRACE	106 -> [0,18,"Marionette:SetContext",{"value":"content"}]
[task 2018-11-13T14:02:56.717Z] 14:02:56     INFO - TEST-UNEXPECTED-FAIL | testing/marionette/harness/marionette_harness/tests/unit/test_window_rect.py TestWindowRect.test_set_position_and_size | AssertionError: 0 != 10
[task 2018-11-13T14:02:56.720Z] 14:02:56     INFO - Traceback (most recent call last):
[task 2018-11-13T14:02:56.721Z] 14:02:56     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 159, in run
[task 2018-11-13T14:02:56.722Z] 14:02:56     INFO -     testMethod()
[task 2018-11-13T14:02:56.723Z] 14:02:56     INFO -   File "/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_window_rect.py", line 111, in test_set_position_and_size
[task 2018-11-13T14:02:56.724Z] 14:02:56     INFO -     self.assertEqual(new_rect["x"], wanted_rect["x"])
[task 2018-11-13T14:02:56.725Z] 14:02:56     INFO - TEST-INFO took 530ms
[task 2018-11-13T14:02:56.727Z] 14:02:56     INFO -  1542117776695	Marionette	TRACE	106 <- [1,18,null,{"value":null}]
[task 2018-11-13T14:02:56.728Z] 14:02:56     INFO -  1542117776699	Marionette	TRACE	106 -> [0,19,"WebDriver:SetWindowRect",{"y":0,"x":0,"width":1280,"height":1040}]
[task 2018-11-13T14:02:56.984Z] 14:02:56     INFO -  1542117776974	Marionette	TRACE	106 <- [1,19,null,{"x":0,"y":0,"width":1280,"height":1040,"state":"normal"}]
[task 2018-11-13T14:02:56.985Z] 14:02:56     INFO -  1542117776976	Marionette	TRACE	106 -> [0,20,"WebDriver:ExecuteScript",{"scriptTimeout":null,"newSandbox":true,"args":[],"filename":"tests/testing/marionette/harness/marionette_harness/tests/unit/test_window_rect.py","script":"return document.fullscreenElement;","sandbox":null,"line":41}]
[task 2018-11-13T14:02:56.994Z] 14:02:56     INFO -  1542117776989	Marionette	TRACE	106 <- [1,20,null,{"value":null}]
[task 2018-11-13T14:02:56.996Z] 14:02:56     INFO -  1542117776991	Marionette	TRACE	106 -> [0,21,"WebDriver:DeleteSession",{}]
[task 2018-11-13T14:02:57.004Z] 14:02:57     INFO -  1542117776997	Marionette	TRACE	106 <- [1,21,null,{"value":null}]

Comment 1

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

Here the except:

https://treeherder.mozilla.org/logviewer.html#?job_id=211425526&repo=try&lineNumber=32215-32225

> 1542117776301  Marionette  TRACE   106 -> [0,8,"WebDriver:GetWindowRect",{}]
> 1542117776304  Marionette  TRACE   106 <- [1,8,null,{"x":0,"y":0,"width":1280,"height":1040,"state":"normal"}]
> 1542117776308  Marionette  TRACE   106 -> [0,9,"WebDriver:SetWindowRect",{"y":10,"x":10,"width":1230,"height":990}]
> 1542117776577  Marionette  TRACE   106 <- [1,9,null,{"x":0,"y":0,"width":1230,"height":990,"state":"normal"}]
> 1542117776584  Marionette  TRACE   106 -> [0,10,"WebDriver:GetWindowRect",{}]
> 1542117776587  Marionette  TRACE   106 <- [1,10,null,{"x":10,"y":10,"width":1230,"height":990,"state":"normal"}]

As it looks like the `WebDriver:SetWindowRect` command returns too early. The requested size has been set, but the position hasn't been reached yet.

Given that I have never seen this failure before, and bug 1492499 landed recently, this might be a regression. But so far it's only that single failure, and I also cannot reproduce locally on MacOS.

Comment 2

[Intermittent Failures Robot]

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

Repository breakdown:
* mozilla-inbound: 1
* mozilla-central: 2
* try: 1

Platform breakdown:
* linux32: 3
* windows10-64: 1

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

Comment 3

[Andreas Tolfsen ❲:ato❳]

This is reminiscent of the DOM property propagation woes we had in
the past.  The response from SetWindowRect {x: 10, y: 10} reports
the X/Y position as (0,0) where we would expect (10,10), then the
next call to GetWindowRect reports (10,10).

This presumably means SetWindowRect doesn’t wait long enough for
the window to reach the requested position.  We can’t await the
position to reach (10,10) because we can never be sure it will ever
reach that due to the uniqueness of the system and its window
manager.

On the other hand, the checks in
https://searchfox.org/mozilla-central/rev/8f89901f2d69d9783f946a7458a6d7ee70635a94/testing/marionette/driver.js#1485-1488
are pretty weak for moving the window’s position.  However, I don’t
have any great ideas for how to improve it.

Comment 4

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

Maybe we should avoid using positions near the sides/edges of the screen for most of the position and size tests, by lets say having a border of 50px for safety? As we don't know what window managers will do, I feel this is the safest bet.

Comment 5

[Intermittent Failures Robot]

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

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

Platform breakdown:
* linux64: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1506894&startday=2018-11-19&endday=2018-11-25&tree=all

Comment 6

[Intermittent Failures Robot]

14 failures in 2808 pushes (0.005 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-inbound: 6
* autoland: 7
* mozilla-central: 1

Platform breakdown:
* linux32: 9
* linux64: 5

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

Comment 7

[Intermittent Failures Robot]

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

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

Platform breakdown:
* linux64: 3

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

Comment 8

[Intermittent Failures Robot]

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

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

Platform breakdown:
* linux64: 2

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

Comment 9

[Intermittent Failures Robot]

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

Repository breakdown:
* mozilla-central: 3
* mozilla-beta: 1
* mozilla-inbound: 3
* autoland: 6

Platform breakdown:
* linux64: 9
* linux32: 4

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

Comment 10

[Intermittent Failures Robot]

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

Repository breakdown:
* mozilla-inbound: 2
* autoland: 4

Platform breakdown:
* linux64: 4
* linux32: 2

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

Comment 11

[Intermittent Failures Robot]

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

Repository breakdown:
* try: 1
* mozilla-inbound: 8
* autoland: 2
* mozilla-central: 2

Platform breakdown:
* linux32: 3
* linux64: 8
* linux32-nightly: 1
* linux64-devedition: 1

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

Comment 12

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 5
• mozilla-central: 2
• try: 2
• mozilla-inbound: 4

Platform breakdown:

• linux32: 6
• linux32-devedition: 1
• linux64: 5
• linux64-nightly: 1

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

Comment 13

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform breakdown:

• linux32: 1

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

Comment 14

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

With bug 1478358 landed the "WebDriver:SetWindowRect" command no longer uses a timed promise to wait for a resize event. I also can no longer see this failure classified via Treeherder. So it should hopefully be fixed.

Comment 15

[BMO Automation]

Moving bug to Testing::Marionette Client and Harness component per bug 1815831.