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

Reporter

Description

•

5 years ago

treeherder

Filed by: btara [at] mozilla.com

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

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

[task 2018-12-31T12:20:23.541Z] 12:20:23     INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_window_rect.py TestWindowRect.test_set_position
[task 2018-12-31T12:20:23.542Z] 12:20:23     INFO -  1546258823532	Marionette	DEBUG	Closed connection 105
[task 2018-12-31T12:20:23.545Z] 12:20:23     INFO -  1546258823535	Marionette	DEBUG	Accepted connection 106 from 127.0.0.1:50640
[task 2018-12-31T12:20:23.546Z] 12:20:23     INFO -  1546258823543	Marionette	DEBUG	106 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2018-12-31T12:20:23.565Z] 12:20:23     INFO -  1546258823555	Marionette	TRACE	[49392123905] Frame script loaded
[task 2018-12-31T12:20:23.566Z] 12:20:23     INFO -  1546258823557	Marionette	TRACE	[49392123905] Frame script registered
[task 2018-12-31T12:20:23.566Z] 12:20:23     INFO -  1546258823560	Marionette	DEBUG	106 <- [1,1,null,{"sessionId":"fd5a3f7a-8e24-4c4c-9bdd-975a80c8228f","capabilities":{"browserName":"firefox","browserVersion":"66.0a ... p/tmp320eYt.mozrunner","moz:shutdownTimeout":180000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2018-12-31T12:20:23.567Z] 12:20:23     INFO -  1546258823564	Marionette	DEBUG	106 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2018-12-31T12:20:23.568Z] 12:20:23     INFO -  1546258823565	Marionette	DEBUG	106 <- [1,2,null,{"value":null}]
[task 2018-12-31T12:20:23.576Z] 12:20:23     INFO -  1546258823571	Marionette	DEBUG	106 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2018-12-31T12:20:23.577Z] 12:20:23     INFO -  1546258823572	Marionette	DEBUG	106 <- [1,3,null,{"value":null}]
[task 2018-12-31T12:20:23.578Z] 12:20:23     INFO -  1546258823574	Marionette	DEBUG	106 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2018-12-31T12:20:23.580Z] 12:20:23     INFO -  1546258823575	Marionette	DEBUG	106 <- [1,4,null,{"value":null}]
[task 2018-12-31T12:20:23.582Z] 12:20:23     INFO -  1546258823579	Marionette	DEBUG	106 -> [0,5,"WebDriver:GetWindowRect",{}]
[task 2018-12-31T12:20:23.592Z] 12:20:23     INFO -  1546258823585	Marionette	DEBUG	106 <- [1,5,null,{"x":0,"y":0,"width":1280,"height":1040,"state":"normal"}]
[task 2018-12-31T12:20:23.592Z] 12:20:23     INFO -  1546258823588	Marionette	DEBUG	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-12-31T12:20:23.609Z] 12:20:23     INFO -  1546258823599	Marionette	DEBUG	106 <- [1,6,null,{"value":{"width":1600,"height":1200}}]
[task 2018-12-31T12:20:23.609Z] 12:20:23     INFO -  1546258823601	Marionette	DEBUG	106 -> [0,7,"WebDriver:SetWindowRect",{"y":null,"x":null,"width":1280,"height":1040}]
[task 2018-12-31T12:20:23.609Z] 12:20:23     INFO -  1546258823605	Marionette	DEBUG	106 <- [1,7,null,{"x":0,"y":0,"width":1280,"height":1040,"state":"normal"}]
[task 2018-12-31T12:20:23.611Z] 12:20:23     INFO -  1546258823608	Marionette	DEBUG	106 -> [0,8,"WebDriver:GetWindowRect",{}]
[task 2018-12-31T12:20:23.619Z] 12:20:23     INFO -  1546258823615	Marionette	DEBUG	106 <- [1,8,null,{"x":0,"y":0,"width":1280,"height":1040,"state":"normal"}]
[task 2018-12-31T12:20:23.620Z] 12:20:23     INFO -  1546258823618	Marionette	DEBUG	106 -> [0,9,"WebDriver:SetWindowRect",{"y":10,"x":10,"width":null,"height":null}]
[task 2018-12-31T12:20:23.636Z] 12:20:23     INFO -  1546258823627	Marionette	DEBUG	106 <- [1,9,null,{"x":0,"y":0,"width":1280,"height":1040,"state":"normal"}]
[task 2018-12-31T12:20:23.637Z] 12:20:23     INFO -  1546258823632	Marionette	DEBUG	106 -> [0,10,"WebDriver:GetWindowRect",{}]
[task 2018-12-31T12:20:23.637Z] 12:20:23     INFO -  1546258823634	Marionette	DEBUG	106 <- [1,10,null,{"x":10,"y":10,"width":1280,"height":1040,"state":"normal"}]
[task 2018-12-31T12:20:23.644Z] 12:20:23     INFO -  1546258823639	Marionette	DEBUG	106 -> [0,11,"Marionette:GetContext",{}]
[task 2018-12-31T12:20:23.645Z] 12:20:23     INFO -  1546258823640	Marionette	DEBUG	106 <- [1,11,null,{"value":"content"}]
[task 2018-12-31T12:20:23.646Z] 12:20:23     INFO -  1546258823642	Marionette	DEBUG	106 -> [0,12,"Marionette:SetContext",{"value":"chrome"}]
[task 2018-12-31T12:20:23.647Z] 12:20:23     INFO -  1546258823643	Marionette	DEBUG	106 <- [1,12,null,{"value":null}]
[task 2018-12-31T12:20:23.656Z] 12:20:23     INFO -  1546258823649	Marionette	DEBUG	106 -> [0,13,"WebDriver:TakeScreenshot",{"highlights":null,"full":true,"hash":false,"id":null,"scroll":true}]
[task 2018-12-31T12:20:23.760Z] 12:20:23     INFO -  1546258823750	Marionette	DEBUG	106 <- [1,13,null,{"value":"iVBORw0KGgoAAAANSUhEUgAABQAAAAQQCAYAAAC9RfbYAAAgAElEQVR4nOzd348V933wcS4r5f+IRNVIiVr5ieRIaVWpF5alNr6Ioyix ... AAAABjAhAAAAAAxgQgAAAAAIwJQAAAAAAYE4AAAAAAMCYAAQAAAGBMAAIAAADAmAAEAAAAgDEBCAAAAABjAhAAAAAAxgJKq633OUzCsgAAAABJRU5ErkJggg=="}]
[task 2018-12-31T12:20:23.761Z] 12:20:23     INFO -  1546258823753	Marionette	DEBUG	106 -> [0,14,"Marionette:SetContext",{"value":"content"}]
[task 2018-12-31T12:20:23.761Z] 12:20:23     INFO -  1546258823754	Marionette	DEBUG	106 <- [1,14,null,{"value":null}]
[task 2018-12-31T12:20:23.761Z] 12:20:23     INFO -  1546258823756	Marionette	DEBUG	106 -> [0,15,"Marionette:GetContext",{}]
[task 2018-12-31T12:20:23.761Z] 12:20:23     INFO -  1546258823756	Marionette	DEBUG	106 <- [1,15,null,{"value":"content"}]
[task 2018-12-31T12:20:23.762Z] 12:20:23     INFO -  1546258823759	Marionette	DEBUG	106 -> [0,16,"Marionette:SetContext",{"value":"content"}]
[task 2018-12-31T12:20:23.780Z] 12:20:23     INFO -  1546258823770	Marionette	DEBUG	106 <- [1,16,null,{"value":null}]
[task 2018-12-31T12:20:23.781Z] 12:20:23     INFO -  1546258823772	Marionette	DEBUG	106 -> [0,17,"WebDriver:GetPageSource",{}]
[task 2018-12-31T12:20:23.789Z] 12:20:23     INFO -  1546258823783	Marionette	DEBUG	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-12-31T12:20:23.791Z] 12:20:23     INFO -  1546258823786	Marionette	DEBUG	106 -> [0,18,"Marionette:SetContext",{"value":"content"}]
[task 2018-12-31T12:20:23.791Z] 12:20:23     INFO -  1546258823788	Marionette	DEBUG	106 <- [1,18,null,{"value":null}]
[task 2018-12-31T12:20:23.813Z] 12:20:23     INFO - TEST-UNEXPECTED-FAIL | testing/marionette/harness/marionette_harness/tests/unit/test_window_rect.py TestWindowRect.test_set_position | AssertionError: 0 != 10
[task 2018-12-31T12:20:23.814Z] 12:20:23     INFO - Traceback (most recent call last):
[task 2018-12-31T12:20:23.814Z] 12:20:23     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 159, in run
[task 2018-12-31T12:20:23.815Z] 12:20:23     INFO -     testMethod()
[task 2018-12-31T12:20:23.815Z] 12:20:23     INFO -   File "/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_window_rect.py", line 81, in test_set_position
[task 2018-12-31T12:20:23.817Z] 12:20:23     INFO -     self.assertEqual(new_position["x"], wanted_position["x"])
[task 2018-12-31T12:20:23.818Z] 12:20:23     INFO - TEST-INFO took 259ms
[task 2018-12-31T12:20:23.819Z] 12:20:23     INFO -  1546258823794	Marionette	DEBUG	106 -> [0,19,"WebDriver:SetWindowRect",{"y":0,"x":0,"width":1280,"height":1040}]
[task 2018-12-31T12:20:23.835Z] 12:20:23     INFO -  1546258823824	Marionette	DEBUG	106 <- [1,19,null,{"x":0,"y":0,"width":1280,"height":1040,"state":"normal"}]
[task 2018-12-31T12:20:23.838Z] 12:20:23     INFO -  1546258823827	Marionette	DEBUG	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-12-31T12:20:23.840Z] 12:20:23     INFO -  1546258823835	Marionette	DEBUG	106 <- [1,20,null,{"value":null}]
[task 2018-12-31T12:20:23.848Z] 12:20:23     INFO -  1546258823841	Marionette	DEBUG	106 -> [0,21,"WebDriver:DeleteSession",{}]
[task 2018-12-31T12:20:23.852Z] 12:20:23     INFO -  1546258823845	Marionette	DEBUG	106 <- [1,21,null,{"value":null}]

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

Assignee

Comment 1

•

5 years ago

> 1546258823618	Marionette	DEBUG	106 -> [0,9,"WebDriver:SetWindowRect",{"y":10,"x":10,"width":null,"height":null}]
> 1546258823627	Marionette	DEBUG	106 <- [1,9,null,{"x":0,"y":0,"width":1280,"height":1040,"state":"normal"}]
> 1546258823632	Marionette	DEBUG	106 -> [0,10,"WebDriver:GetWindowRect",{}]
> 1546258823634	Marionette	DEBUG	106 <- [1,10,null,{"x":10,"y":10,"width":1280,"height":1040,"state":"normal"}]

As it can be seen the "WebDriver:SetWindowRect" command returns too early:

https://searchfox.org/mozilla-central/rev/3e7afaa5b57b3f8ed100cd1f13bb0a93b9b2cb99/testing/marionette/driver.js#1495-1498

So just waiting for the IdlePromise here might not be enough, and `win.moveTo()` might take longer than that. Some more logging would be helpful which will be added through bug 1510940.

Blocks: 1492499

Depends on: 1510940

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

Assignee

Updated

•

5 years ago

Updated

•

5 years ago

Updated

•

5 years ago

Updated

•

5 years ago

Depends on: 1517414

Comment hidden (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: 2

Platform breakdown:
* linux64: 2

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

Comment hidden (Intermittent Failures Robot)

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

Assignee

Comment 4

•

5 years ago

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.

Assignee: nobody → hskupin

Status: NEW → RESOLVED

Closed: 5 years ago

status-firefox65: --- → fixed

status-firefox66: --- → fixed

Depends on: 1478358
No longer depends on: 1517414

Resolution: --- → FIXED

Target Milestone: --- → mozilla66

BMO Automation

Updated

•

1 year ago

Product: Testing → Remote Protocol

BMO Automation

Comment 5

•

1 year ago

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

Component: Marionette → Marionette Client and Harness

Product: Remote Protocol → Testing

Bugzilla

Quick Search

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

Categories

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

Tracking

(firefox65 fixed, firefox66 fixed)

People

(Reporter: intermittent-bug-filer, Assigned: whimboo)

References

(Depends on 1 open bug)

Details

(Keywords: intermittent-failure)

Crash Data

Security

(public)

User Story

Description

Comment 1

Updated

Updated

Updated

Updated

Comment 2

Comment 3

Comment 4

Updated

Comment 5