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}]

> 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.

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