1506245 - Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_window_rect.py TestWindowRect.test_resize_while_fullscreen | TimeoutException:

Status: RESOLVED INCOMPLETE

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

Description

[Treeherder Bug Filer]

Filed by: apavel [at] mozilla.com

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

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

11:00:43     INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_window_rect.py TestWindowRect.test_resize_while_fullscreen
11:00:43     INFO -  1541790043722	Marionette	TRACE	103 <- [1,12,null,{"value":null}]
11:00:43     INFO -  1541790043724	Marionette	DEBUG	Closed connection 103
11:00:43     INFO -  1541790043725	Marionette	DEBUG	Accepted connection 104 from 127.0.0.1:51747
11:00:43     INFO -  1541790043726	Marionette	TRACE	104 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
11:00:43     INFO -  1541790043727	Marionette	DEBUG	[8589934608] Frame script loaded
11:00:43     INFO -  1541790043727	Marionette	DEBUG	[2147483905] Frame script loaded
11:00:43     INFO -  1541790043728	Marionette	DEBUG	[8589934608] Frame script registered
11:00:43     INFO -  1541790043728	Marionette	DEBUG	[2147483905] Frame script registered
11:00:43     INFO -  1541790043729	Marionette	TRACE	104 <- [1,1,null,{"sessionId":"b48c74dd-e82f-064a-913a-8240b41981d2","capabilities":{"browserName":"firefox","browserVersion":"65.0a ... /T/tmpJ5jf6z.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
11:00:43     INFO -  1541790043731	Marionette	TRACE	104 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
11:00:43     INFO -  1541790043732	Marionette	TRACE	104 <- [1,2,null,{"value":null}]
11:00:43     INFO -  1541790043732	Marionette	TRACE	104 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
11:00:43     INFO -  1541790043733	Marionette	TRACE	104 <- [1,3,null,{"value":null}]
11:00:43     INFO -  1541790043733	Marionette	TRACE	104 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
11:00:43     INFO -  1541790043734	Marionette	TRACE	104 <- [1,4,null,{"value":null}]
11:00:43     INFO -  1541790043734	Marionette	TRACE	104 -> [0,5,"WebDriver:GetWindowRect",{}]
11:00:43     INFO -  1541790043735	Marionette	TRACE	104 <- [1,5,null,{"x":4,"y":23,"width":1280,"height":1009,"state":"normal"}]
11:00:43     INFO -  1541790043736	Marionette	TRACE	104 -> [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}]
11:00:43     INFO -  1541790043739	Marionette	TRACE	104 <- [1,6,null,{"value":{"width":1600,"height":1097}}]
11:00:43     INFO -  1541790043740	Marionette	TRACE	104 -> [0,7,"WebDriver:SetWindowRect",{"y":null,"x":null,"width":1280,"height":1009}]
11:00:43     INFO -  1541790043741	Marionette	TRACE	104 <- [1,7,null,{"x":4,"y":23,"width":1280,"height":1009,"state":"normal"}]
11:00:43     INFO -  1541790043742	Marionette	TRACE	104 -> [0,8,"WebDriver:FullscreenWindow",{}]
11:00:45     INFO -  1541790045067	Marionette	TRACE	104 <- [1,8,null,{"x":0,"y":0,"width":1600,"height":1200,"state":"fullscreen"}]
11:00:45     INFO -  1541790045068	Marionette	TRACE	104 -> [0,9,"WebDriver:SetWindowRect",{"y":null,"x":null,"width":1500,"height":997}]
11:00:46     INFO -  1541790046570	Marionette	TRACE	104 <- [1,9,{"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]
11:00:46     INFO -  1541790046572	Marionette	TRACE	104 -> [0,10,"Marionette:GetContext",{}]
11:00:46     INFO -  1541790046572	Marionette	TRACE	104 <- [1,10,null,{"value":"content"}]
11:00:46     INFO -  1541790046573	Marionette	TRACE	104 -> [0,11,"Marionette:SetContext",{"value":"chrome"}]
11:00:46     INFO -  1541790046573	Marionette	TRACE	104 <- [1,11,null,{"value":null}]
11:00:46     INFO -  1541790046574	Marionette	TRACE	104 -> [0,12,"WebDriver:TakeScreenshot",{"highlights":null,"full":true,"hash":false,"id":null,"scroll":true}]
11:00:46     INFO -  1541790046612	Marionette	TRACE	104 <- [1,12,null,{"value":"iVBORw0KGgoAAAANSUhEUgAABQAAAAPxCAYAAACl+gBxAAAgAElEQVR4nOzdXWyV953o+3UuRto6c7Okfbk10mgu9qgX7pzqeM90OkLZ ... Kq7R2W8pS77b9PnsL8+wiAAAAAAK+LAPjKvXil4npRs9nVs6sPfxcBEAAAAOB1EQD5pQRAAAAAgNdFAOSXEgABAAAAXpf/AXWv0KH3dZxYAAAAAElFTkSuQmCC"}]
11:00:46     INFO -  1541790046613	Marionette	TRACE	104 -> [0,13,"Marionette:SetContext",{"value":"content"}]
11:00:46     INFO -  1541790046614	Marionette	TRACE	104 <- [1,13,null,{"value":null}]
11:00:46     INFO -  1541790046615	Marionette	TRACE	104 -> [0,14,"Marionette:GetContext",{}]
11:00:46     INFO -  1541790046615	Marionette	TRACE	104 <- [1,14,null,{"value":"content"}]
11:00:46     INFO -  1541790046616	Marionette	TRACE	104 -> [0,15,"Marionette:SetContext",{"value":"content"}]
11:00:46     INFO -  1541790046616	Marionette	TRACE	104 <- [1,15,null,{"value":null}]
11:00:46     INFO -  1541790046616	Marionette	TRACE	104 -> [0,16,"WebDriver:GetPageSource",{}]
11:00:46     INFO - TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_window_rect.py TestWindowRect.test_resize_while_fullscreen | TimeoutException: 
11:00:46     INFO - stacktrace:
11:00:46     INFO - 	WebDriverError@chrome://marionette/content/error.js:179:5
11:00:46     INFO - 	TimeoutError@chrome://marionette/content/error.js:446:5
11:00:46     INFO - 	bail@chrome://marionette/content/sync.js:193:19
11:00:46     INFO - Traceback (most recent call last):
11:00:46     INFO -   File "/Users/cltbld/tasks/task_1541789757/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 159, in run
11:00:46     INFO -     testMethod()
11:00:46     INFO -   File "/Users/cltbld/tasks/task_1541789757/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_window_rect.py", line 223, in test_resize_while_fullscreen
11:00:46     INFO -     height=self.max["height"] - 100)
11:00:46     INFO -   File "/Users/cltbld/tasks/task_1541789757/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 1386, in set_window_rect
11:00:46     INFO -     body)
11:00:46     INFO -   File "/Users/cltbld/tasks/task_1541789757/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 26, in _
11:00:46     INFO -     return func(*args, **kwargs)
11:00:46     INFO -   File "/Users/cltbld/tasks/task_1541789757/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 764, in _send_message
11:00:46     INFO -     self._handle_error(err)
11:00:46     INFO -   File "/Users/cltbld/tasks/task_1541789757/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 784, in _handle_error
11:00:46     INFO -     raise errors.lookup(error)(message, stacktrace=stacktrace)
11:00:46     INFO - TEST-INFO took 2896ms
11:00:46     INFO -  1541790046618	Marionette	TRACE	104 <- [1,16,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>"}]
11:00:46     INFO -  1541790046619	Marionette	TRACE	104 -> [0,17,"Marionette:SetContext",{"value":"content"}]
11:00:46     INFO -  1541790046619	Marionette	TRACE	104 <- [1,17,null,{"value":null}]
11:00:46     INFO -  1541790046622	Marionette	TRACE	104 -> [0,18,"WebDriver:SetWindowRect",{"y":23,"x":4,"width":1280,"height":1009}]
11:00:46     INFO -  1541790046623	Marionette	TRACE	104 <- [1,18,null,{"x":4,"y":23,"width":1280,"height":1009,"state":"normal"}]
11:00:46     INFO -  1541790046625	Marionette	TRACE	104 -> [0,19,"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}]
11:00:46     INFO -  1541790046628	Marionette	TRACE	104 <- [1,19,null,{"value":null}]
11:00:46     INFO -  1541790046628	Marionette	TRACE	104 -> [0,20,"WebDriver:DeleteSession",{}]

Comment 1

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

SetWindowRect times out, which is now a new behavior since bug 1492499 is fixed.

Comment 2

[Intermittent Failures Robot]

1 failures in 3007 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=1506245&startday=2018-11-05&endday=2018-11-11&tree=all

Comment 3

[Intermittent Failures Robot]

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

Repository breakdown:
* mozilla-central: 1

Platform breakdown:
* windows10-64: 1

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

Comment 4

[Andreas Tolfsen ❲:ato❳]

Like https://bugzilla.mozilla.org/show_bug.cgi?id=1509224, it seems
to happen very frequently, almost to the point where reproducing
it on try I would suspect is like finding a needle in a haystack.

There seems to be a pattern that it manifests on Windows 10 x64 and
osx-10-10, however I can’t tell from OF if it is for headless or
not.  Is this information available through OF?

Comment 5

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

You will have to click the OF graph at the top of the bug, and check the `Test Suite` column of the table.

Comment 6

[Andreas Tolfsen ❲:ato❳]

So the last OF report three days ago in
https://bugzilla.mozilla.org/show_bug.cgi?id=1506245#c3 is a mochitest
failure with the failure message:

> TEST-UNEXPECTED-TIMEOUT | automation.py | application timed out after 370 seconds with no output

It seems to be about a hang during startup:

> 23:00:48     INFO - GECKO(6448) | 1542495648146	Marionette	DEBUG	Received observer notification profile-after-change
> 23:00:48     INFO - GECKO(6448) | 1542495648204	Marionette	DEBUG	Received observer notification toplevel-window-ready
> 23:00:48     INFO - GECKO(6448) | 1542495648238	Marionette	DEBUG	Received observer notification command-line-startup
> 23:00:48     INFO - GECKO(6448) | 1542495648238	Marionette	DEBUG	Received observer notification nsPref:changed
> 23:00:48     INFO - GECKO(6448) | 1542495648238	Marionette	DEBUG	Init aborted (running=false, enabled=true, finalUIStartup=false)
> 23:03:47     INFO - runtests.py | Waiting for browser...
> 23:06:58     INFO - Buffered messages finished
> 23:06:58    ERROR - TEST-UNEXPECTED-TIMEOUT | automation.py | application timed out after 370 seconds with no output

The one ten days ago in
https://bugzilla.mozilla.org/show_bug.cgi?id=1506245#c2 is osx-10-10
related; the same as original report.

Comment 7

[Intermittent Failures Robot]

1 failures in 2485 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=1506245&startday=2018-12-10&endday=2018-12-16&tree=all

Comment 8

[Intermittent Failures Robot]

1 failures in 2648 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=1506245&startday=2018-12-17&endday=2018-12-23&tree=all

Comment 9

[Intermittent Failures Robot]

1 failures in 1668 pushes (0.001 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=1506245&startday=2018-12-31&endday=2019-01-06&tree=all

Comment 10

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1
• mozilla-inbound: 1

Platform breakdown:

• osx-10-10: 2

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

Comment 11

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

Recent failures show timeouts when switching into fullscreen mode:

02:47:41 INFO - 1547117261987 Marionette DEBUG 105 -> [0,8,"WebDriver:FullscreenWindow",{}]
02:47:43 INFO - 1547117263493 Marionette WARN TimedPromise timed out after 1500 ms: stacktrace:
02:47:43 INFO - bail@chrome://marionette/content/sync.js:196:64

I filed bug 1519777.

Comment 12

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1
• mozilla-beta: 1

Platform breakdown:

• macosx64-nightly: 1
• osx-10-10: 1

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

Comment 13

[Firefox Bug Husbandry Bot]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup

Comment 14

[BMO Automation]

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