Closed Bug 1500298 Opened 7 years ago Closed 7 years ago

Intermittent ../../checkouts/gecko/toolkit/components/telemetry/tests/marionette/tests/client/test_main_tab_scalars.py TestMainTabScalars.test_main_tab_scalars | AssertionError: Error generating ping: Timed out after 60.0 seconds

Categories

(Toolkit :: Telemetry, defect, P1)

defect

Tracking

()

RESOLVED FIXED
mozilla65
Tracking Status
firefox64 --- fixed
firefox65 --- fixed

People

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

References

Details

(Keywords: intermittent-failure)

Attachments

(1 file, 1 obsolete file)

Filed by: aiakab [at] mozilla.com https://treeherder.mozilla.org/logviewer.html#?job_id=206501419&repo=autoland https://queue.taskcluster.net/v1/task/NbPAw_kTShqG7pl_CTCYOg/runs/0/artifacts/public/logs/live_backing.log 00:44:50 INFO - [Child 1346, Main Thread] WARNING: Fallback to BasicLayerManager: file /builds/worker/workspace/build/src/dom/ipc/TabChild.cpp, line 2839 [task 2018-10-19T00:44:50.776Z] 00:44:50 INFO - ++DOMWINDOW == 4 (0x7f70c9df7400) [pid = 1346] [serial = 4] [outer = 0x7f70dfa52a00] [task 2018-10-19T00:44:50.821Z] 00:44:50 INFO - ++DOMWINDOW == 5 (0x7f70c9960000) [pid = 1346] [serial = 5] [outer = 0x7f70dfa56c00] [task 2018-10-19T00:44:50.890Z] 00:44:50 INFO - ++DOMWINDOW == 6 (0x7f70c9963800) [pid = 1346] [serial = 6] [outer = 0x7f70dfa57800] [task 2018-10-19T00:44:50.912Z] 00:44:50 INFO - ++DOCSHELL 0x7f70c99b7000 == 4 [pid = 1346] [id = {a7edf63c-3a65-4da9-a96e-f28c350c3378}] [task 2018-10-19T00:44:50.913Z] 00:44:50 INFO - [Child 1346, Main Thread] WARNING: NS_ENSURE_TRUE(browserChrome) failed: file /builds/worker/workspace/build/src/docshell/base/nsDocShell.cpp, line 12587 [task 2018-10-19T00:44:50.914Z] 00:44:50 INFO - ++DOMWINDOW == 7 (0x7f70c994f200) [pid = 1346] [serial = 7] [outer = (nil)] [task 2018-10-19T00:44:50.930Z] 00:44:50 INFO - [Child 1346, Main Thread] WARNING: Fallback to BasicLayerManager: file /builds/worker/workspace/build/src/dom/ipc/TabChild.cpp, line 2839 [task 2018-10-19T00:44:50.947Z] 00:44:50 INFO - ++DOMWINDOW == 8 (0x7f70c9964c00) [pid = 1346] [serial = 8] [outer = 0x7f70c994f200] [task 2018-10-19T00:44:50.983Z] 00:44:50 INFO - ++DOMWINDOW == 9 (0x7f70c9d55c00) [pid = 1346] [serial = 9] [outer = 0x7f70dfa52a00] [task 2018-10-19T00:44:51.000Z] 00:44:50 INFO - ++DOMWINDOW == 10 (0x7f70c893d800) [pid = 1346] [serial = 10] [outer = 0x7f70dfa56c00] [task 2018-10-19T00:44:51.016Z] 00:44:51 INFO - ++DOMWINDOW == 11 (0x7f70c893e800) [pid = 1346] [serial = 11] [outer = 0x7f70dfa57800] [task 2018-10-19T00:44:51.037Z] 00:44:51 INFO - ++DOMWINDOW == 12 (0x7f70c8940000) [pid = 1346] [serial = 12] [outer = 0x7f70c994f200] [task 2018-10-19T00:44:51.317Z] 00:44:51 INFO - 1539909891308 Marionette DEBUG Waiting for startup tests... [task 2018-10-19T00:44:51.434Z] 00:44:51 INFO - 1539909891426 Marionette INFO Listening on port 2828 [task 2018-10-19T00:44:51.435Z] 00:44:51 INFO - 1539909891427 Marionette DEBUG Remote service is active [task 2018-10-19T00:44:51.533Z] 00:44:51 INFO - 1539909891522 Marionette DEBUG Accepted connection 0 from 127.0.0.1:42294 [task 2018-10-19T00:44:51.562Z] 00:44:51 INFO - 1539909891553 Marionette DEBUG Closed connection 0 [task 2018-10-19T00:44:51.564Z] 00:44:51 INFO - 1539909891557 Marionette DEBUG Accepted connection 1 from 127.0.0.1:42296 [task 2018-10-19T00:44:51.585Z] 00:44:51 INFO - 1539909891581 Marionette TRACE 1 -> [0,1,"WebDriver:NewSession",{}] [task 2018-10-19T00:44:51.889Z] 00:44:51 INFO - 1539909891881 Marionette DEBUG [2147483649] Frame script loaded [task 2018-10-19T00:44:51.930Z] 00:44:51 INFO - 1539909891917 Marionette DEBUG [2147483649] Frame script registered [task 2018-10-19T00:44:51.983Z] 00:44:51 INFO - 1539909891977 Marionette TRACE 1 <- [1,1,null,{"sessionId":"ba4cebb6-87c7-4c0a-be7d-b9611d4cf947","capabilities":{"browserName":"firefox","browserVersion":"64.0a ... /builds/worker/workspace/build/tmphG2fSJ.mozrunner","moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}] [task 2018-10-19T00:44:52.025Z] 00:44:52 INFO - 1539909892023 Marionette TRACE 1 -> [0,2,"Marionette:SetContext",{"value":"chrome"}] [task 2018-10-19T00:44:52.033Z] 00:44:52 INFO - 1539909892027 Marionette TRACE 1 <- [1,2,null,{"value":null}] [task 2018-10-19T00:44:52.036Z] 00:44:52 INFO - 1539909892032 Marionette TRACE 1 -> [0,3,"WebDriver:GetChromeWindowHandles",{}] [task 2018-10-19T00:44:52.037Z] 00:44:52 INFO - 1539909892035 Marionette TRACE 1 <- [1,3,null,["1"]] [task 2018-10-19T00:44:52.046Z] 00:44:52 INFO - 1539909892041 Marionette TRACE 1 -> [0,4,"WebDriver:GetChromeWindowHandle",{}] [task 2018-10-19T00:44:52.047Z] 00:44:52 INFO - 1539909892043 Marionette TRACE 1 <- [1,4,null,{"value":"1"}] [task 2018-10-19T00:44:52.055Z] 00:44:52 INFO - 1539909892050 Marionette TRACE 1 -> [0,5,"WebDriver:GetChromeWindowHandles",{}] [task 2018-10-19T00:44:52.058Z] 00:44:52 INFO - 1539909892053 Marionette TRACE 1 <- [1,5,null,["1"]] [task 2018-10-19T00:44:52.075Z] 00:44:52 INFO - 1539909892064 Marionette TRACE 1 -> [0,6,"WebDriver:SwitchToWindow",{"focus":true,"name":"1"}] [task 2018-10-19T00:44:52.077Z] 00:44:52 INFO - 1539909892068 Marionette TRACE 1 <- [1,6,null,{"value":null}] [task 2018-10-19T00:44:52.079Z] 00:44:52 INFO - 1539909892074 Marionette TRACE 1 -> [0,7,"WebDriver:GetChromeWindowHandle",{}] [task 2018-10-19T00:44:52.088Z] 00:44:52 INFO - 1539909892082 Marionette TRACE 1 <- [1,7,null,{"value":"1"}] [task 2018-10-19T00:44:52.091Z] 00:44:52 INFO - 1539909892086 Marionette TRACE 1 -> [0,8,"Marionette:GetContext",{}] [task 2018-10-19T00:44:52.100Z] 00:44:52 INFO - 1539909892093 Marionette TRACE 1 <- [1,8,null,{"value":"chrome"}] [task 2018-10-19T00:44:52.109Z] 00:44:52 INFO - 1539909892102 Marionette TRACE 1 -> [0,9,"Marionette:SetContext",{"value":"chrome"}] [task 2018-10-19T00:44:52.112Z] 00:44:52 INFO - 1539909892105 Marionette TRACE 1 <- [1,9,null,{"value":null}] [task 2018-10-19T00:44:52.128Z] 00:44:52 INFO - 1539909892119 Marionette TRACE 1 -> [0,10,"WebDriver:GetChromeWindowHandle",{}] [task 2018-10-19T00:44:52.131Z] 00:44:52 INFO - 1539909892121 Marionette TRACE 1 <- [1,10,null,{"value":"1"}] [task 2018-10-19T00:44:52.148Z] 00:44:52 INFO - 1539909892139 Marionette TRACE 1 -> [0,11,"Marionette:GetWindowType",{}] [task 2018-10-19T00:44:52.152Z] 00:44:52 INFO - 1539909892147 Marionette TRACE 1 <- [1,11,null,{"value":"navigator:browser"}] [task 2018-10-19T00:44:52.163Z] 00:44:52 INFO - 1539909892158 Marionette TRACE 1 -> [0,12,"WebDriver:GetChromeWindowHandles",{}] [task 2018-10-19T00:44:52.163Z] 00:44:52 INFO - 1539909892160 Marionette TRACE 1 <- [1,12,null,["1"]] [task 2018-10-19T00:44:52.172Z] 00:44:52 INFO - 1539909892167 Marionette TRACE 1 -> [0,13,"Marionette:GetContext",{}] [task 2018-10-19T00:44:52.172Z] 00:44:52 INFO - 1539909892168 Marionette TRACE 1 <- [1,13,null,{"value":"chrome"}] [task 2018-10-19T00:44:52.180Z] 00:44:52 INFO - 1539909892173 Marionette TRACE 1 -> [0,14,"Marionette:SetContext",{"value":"chrome"}] [task 2018-10-19T00:44:52.180Z] 00:44:52 INFO - 1539909892175 Marionette TRACE 1 <- [1,14,null,{"value":null}] [task 2018-10-19T00:44:52.216Z] 00:44:52 INFO - 1539909892206 Marionette TRACE 1 -> [0,15,"WebDriver:ExecuteScript",{"scriptTimeout":null,"newSandbox":true,"args":["1"],"filename":"venv/lib/python2.7/site-pack ... wWithId(Number(arguments[0]));\n return win.document.readyState == 'complete';","sandbox":"default","line":157}] [task 2018-10-19T00:44:52.224Z] 00:44:52 INFO - 1539909892220 Marionette TRACE 1 <- [1,15,null,{"value":true}] [task 2018-10-19T00:44:52.233Z] 00:44:52 INFO - 1539909892225 Marionette TRACE 1 -> [0,16,"Marionette:SetContext",{"value":"chrome"}] [task 2018-10-19T00:44:52.234Z] 00:44:52 INFO - 1539909892227 Marionette TRACE 1 <- [1,16,null,{"value":null}] [task 2018-10-19T00:44:52.234Z] 00:44:52 INFO - 1539909892230 Marionette TRACE 1 -> [0,17,"Marionette:SetContext",{"value":"chrome"}] [task 2018-10-19T00:44:52.244Z] 00:44:52 INFO - 1539909892236 Marionette TRACE 1 <- [1,17,null,{"value":null}] [task 2018-10-19T00:44:52.244Z] 00:44:52 INFO - 1539909892239 Marionette TRACE 1 -> [0,18,"WebDriver:SwitchToWindow",{"focus":true,"name":"1"}] [task 2018-10-19T00:44:52.246Z] 00:44:52 INFO - 1539909892242 Marionette TRACE 1 <- [1,18,null,{"value":null}] [task 2018-10-19T00:44:52.254Z] 00:44:52 INFO - 1539909892249 Marionette TRACE 1 -> [0,19,"WebDriver:GetChromeWindowHandle",{}] [task 2018-10-19T00:44:52.255Z] 00:44:52 INFO - 1539909892251 Marionette TRACE 1 <- [1,19,null,{"value":"1"}] [task 2018-10-19T00:44:52.263Z] 00:44:52 INFO - 1539909892256 Marionette TRACE 1 -> [0,20,"Marionette:GetContext",{}] [task 2018-10-19T00:44:52.264Z] 00:44:52 INFO - 1539909892258 Marionette TRACE 1 <- [1,20,null,{"value":"chrome"}] [task 2018-10-19T00:44:52.264Z] 00:44:52 INFO - 1539909892261 Marionette TRACE 1 -> [0,21,"Marionette:SetContext",{"value":"chrome"}] [task 2018-10-19T00:44:52.273Z] 00:44:52 INFO - 1539909892268 Marionette TRACE 1 <- [1,21,null,{"value":null}] [task 2018-10-19T00:44:52.273Z] 00:44:52 INFO - 1539909892271 Marionette TRACE 1 -> [0,22,"WebDriver:GetChromeWindowHandle",{}] [task 2018-10-19T00:44:52.277Z] 00:44:52 INFO - 1539909892275 Marionette TRACE 1 <- [1,22,null,{"value":"1"}] [task 2018-10-19T00:44:52.281Z] 00:44:52 INFO - 1539909892279 Marionette TRACE 1 -> [0,23,"Marionette:GetWindowType",{}] [task 2018-10-19T00:44:52.284Z] 00:44:52 INFO - 1539909892281 Marionette TRACE 1 <- [1,23,null,{"value":"navigator:browser"}] [task 2018-10-19T00:44:52.293Z] 00:44:52 INFO - 1539909892285 Marionette TRACE 1 -> [0,24,"WebDriver:GetChromeWindowHandles",{}] [task 2018-10-19T00:44:52.293Z] 00:44:52 INFO - 1539909892288 Marionette TRACE 1 <- [1,24,null,["1"]] [task 2018-10-19T00:44:52.294Z] 00:44:52 INFO - 1539909892291 Marionette TRACE 1 -> [0,25,"Marionette:GetContext",{}] [task 2018-10-19T00:44:52.298Z] 00:44:52 INFO - 1539909892295 Marionette TRACE 1 <- [1,25,null,{"value":"chrome"}] [task 2018-10-19T00:44:52.302Z] 00:44:52 INFO - 1539909892300 Marionette TRACE 1 -> [0,26,"Marionette:SetContext",{"value":"chrome"}] [task 2018-10-19T00:44:52.305Z] 00:44:52 INFO - 1539909892303 Marionette TRACE 1 <- [1,26,null,{"value":null}] [task 2018-10-19T00:44:52.313Z] 00:44:52 INFO - 1539909892308 Marionette TRACE 1 -> [0,27,"WebDriver:ExecuteScript",{"scriptTimeout":null,"newSandbox":true,"args":["1"],"filename":"venv/lib/python2.7/site-pack ... wWithId(Number(arguments[0]));\n return win.document.readyState == 'complete';","sandbox":"default","line":157}] [task 2018-10-19T00:44:52.329Z] 00:44:52 INFO - 1539909892321 Marionette TRACE 1 <- [1,27,null,{"value":true}] [task 2018-10-19T00:44:52.347Z] 00:44:52 INFO - 1539909892336 Marionette TRACE 1 -> [0,28,"Marionette:SetContext",{"value":"chrome"}] [task 2018-10-19T00:44:52.348Z] 00:44:52 INFO - 1539909892340 Marionette TRACE 1 <- [1,28,null,{"value":null}] [task 2018-10-19T00:44:52.384Z] 00:44:52 INFO - 1539909892381 Marionette TRACE 1 -> [0,29,"Marionette:SetContext",{"value":"chrome"}] [task 2018-10-19T00:44:52.386Z] 00:44:52 INFO - 1539909892384 Marionette TRACE 1 <- [1,29,null,{"value":null}] [task 2018-10-19T00:44:52.791Z] 00:44:52 INFO - Couldn't convert chrome URL: chrome://branding/locale/brand.properties [task 2018-10-19T00:44:57.936Z] 00:44:57 INFO - --DOCSHELL 0x7f91ef5c8800 == 7 [pid = 1024] [id = {548f446e-ddc7-4f2b-8368-0efdab7f4758}] [task 2018-10-19T00:45:02.005Z] 00:45:02 INFO - --DOMWINDOW == 24 (0x7f91f6b99c00) [pid = 1024] [serial = 4] [outer = (nil)] [url = about:blank] [task 2018-10-19T00:45:02.007Z] 00:45:02 INFO - --DOMWINDOW == 23 (0x7f91eaddf400) [pid = 1024] [serial = 12] [outer = (nil)] [url = about:blank] [task 2018-10-19T00:45:02.007Z] 00:45:02 INFO - --DOMWINDOW == 22 (0x7f91eadde800) [pid = 1024] [serial = 11] [outer = (nil)] [url = about:blank] [task 2018-10-19T00:45:02.008Z] 00:45:02 INFO - --DOMWINDOW == 21 (0x7f91eade0800) [pid = 1024] [serial = 15] [outer = (nil)] [url = about:blank] [task 2018-10-19T00:45:02.008Z] 00:45:02 INFO - --DOMWINDOW == 20 (0x7f91eade0000) [pid = 1024] [serial = 14] [outer = (nil)] [url = about:blank] [task 2018-10-19T00:45:02.009Z] 00:45:02 INFO - --DOMWINDOW == 19 (0x7f91eb9abc00) [pid = 1024] [serial = 18] [outer = (nil)] [url = about:blank] [task 2018-10-19T00:45:02.009Z] 00:45:02 INFO - --DOMWINDOW == 18 (0x7f91eb9ab000) [pid = 1024] [serial = 17] [outer = (nil)] [url = about:blank] [task 2018-10-19T00:45:02.010Z] 00:45:02 INFO - --DOMWINDOW == 17 (0x7f91eb9adc00) [pid = 1024] [serial = 21] [outer = (nil)] [url = about:blank] [task 2018-10-19T00:45:02.010Z] 00:45:02 INFO - --DOMWINDOW == 16 (0x7f91eb9acc00) [pid = 1024] [serial = 20] [outer = (nil)] [url = about:blank] [task 2018-10-19T00:45:03.921Z] 00:45:03 INFO - --DOMWINDOW == 3 (0x7fe83795e800) [pid = 1286] [serial = 2] [outer = (nil)] [url = about:blank] [task 2018-10-19T00:45:03.922Z] 00:45:03 INFO - --DOMWINDOW == 2 (0x7fe837ad0000) [pid = 1286] [serial = 3] [outer = (nil)] [url = about:blank] [task 2018-10-19T00:45:04.407Z] 00:45:04 INFO - --DOMWINDOW == 15 (0x7f91efce1e00) [pid = 1024] [serial = 7] [outer = (nil)] [url = about:blank] [task 2018-10-19T00:45:05.383Z] 00:45:05 INFO - --DOMWINDOW == 11 (0x7f70c9df7400) [pid = 1346] [serial = 4] [outer = (nil)] [url = about:blank] [task 2018-10-19T00:45:05.384Z] 00:45:05 INFO - --DOMWINDOW == 10 (0x7f70c9960000) [pid = 1346] [serial = 5] [outer = (nil)] [url = about:blank] [task 2018-10-19T00:45:05.385Z] 00:45:05 INFO - --DOMWINDOW == 9 (0x7f70c9964c00) [pid = 1346] [serial = 8] [outer = (nil)] [url = about:blank] [task 2018-10-19T00:45:05.385Z] 00:45:05 INFO - --DOMWINDOW == 8 (0x7f70c9963800) [pid = 1346] [serial = 6] [outer = (nil)] [url = about:blank] [task 2018-10-19T00:45:07.321Z] 00:45:07 INFO - --DOMWINDOW == 14 (0x7f91ef205800) [pid = 1024] [serial = 8] [outer = (nil)] [url = about:blank] [task 2018-10-19T00:45:08.935Z] 00:45:08 INFO - [Parent 1024, StreamTrans #43] WARNING: 'NS_FAILED(rv)', file /builds/worker/workspace/build/src/modules/libjar/nsJARChannel.cpp, line 419 [task 2018-10-19T00:45:08.935Z] 00:45:08 INFO - [Parent 1024, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012: file /builds/worker/workspace/build/src/modules/libjar/nsJARChannel.cpp, line 1127 [task 2018-10-19T00:45:52.403Z] 00:45:52 INFO - 1539909952401 Marionette TRACE 1 -> [0,30,"Marionette:GetContext",{}] [task 2018-10-19T00:45:52.408Z] 00:45:52 INFO - 1539909952404 Marionette TRACE 1 <- [1,30,null,{"value":"chrome"}] [task 2018-10-19T00:45:52.416Z] 00:45:52 INFO - 1539909952412 Marionette TRACE 1 -> [0,31,"Marionette:SetContext",{"value":"chrome"}] [task 2018-10-19T00:45:52.418Z] 00:45:52 INFO - 1539909952414 Marionette TRACE 1 <- [1,31,null,{"value":null}] [task 2018-10-19T00:45:52.426Z] 00:45:52 INFO - 1539909952419 Marionette TRACE 1 -> [0,32,"WebDriver:TakeScreenshot",{"highlights":null,"full":true,"hash":false,"id":null,"scroll":true}] [task 2018-10-19T00:45:52.488Z] 00:45:52 INFO - 1539909952484 Marionette TRACE 1 <- [1,32,null,{"value":"iVBORw0KGgoAAAANSUhEUgAABQAAAAQQCAYAAAC9RfbYAAAgAElEQVR4nOzdzW9c92HucS8L9P8IkAJFd76LFOgmS2+Lu8zCEJfu3Rha ... QAAACAMQEIAAAAAGMCEAAAAADGBCAAAAAAjAlAAAAAABgTgAAAAAAwJgABAAAAYEwAAgAAAMCYAAQAAACAMQEIAAAAAGMB9MPMXXzG24QAAAAASUVORK5CYII="}] [task 2018-10-19T00:45:52.493Z] 00:45:52 INFO - 1539909952490 Marionette TRACE 1 -> [0,33,"Marionette:SetContext",{"value":"chrome"}] [task 2018-10-19T00:45:52.496Z] 00:45:52 INFO - 1539909952493 Marionette TRACE 1 <- [1,33,null,{"value":null}] [task 2018-10-19T00:45:52.501Z] 00:45:52 INFO - 1539909952498 Marionette TRACE 1 -> [0,34,"Marionette:GetContext",{}] [task 2018-10-19T00:45:52.503Z] 00:45:52 INFO - 1539909952500 Marionette TRACE 1 <- [1,34,null,{"value":"chrome"}] [task 2018-10-19T00:45:52.520Z] 00:45:52 INFO - 1539909952510 Marionette TRACE 1 -> [0,35,"Marionette:SetContext",{"value":"content"}] [task 2018-10-19T00:45:52.521Z] 00:45:52 INFO - 1539909952512 Marionette TRACE 1 <- [1,35,null,{"value":null}] [task 2018-10-19T00:45:52.521Z] 00:45:52 INFO - 1539909952515 Marionette TRACE 1 -> [0,36,"WebDriver:GetPageSource",{}] [task 2018-10-19T00:45:52.550Z] 00:45:52 INFO - TEST-UNEXPECTED-FAIL | ../../checkouts/gecko/toolkit/components/telemetry/tests/marionette/tests/client/test_main_tab_scalars.py TestMainTabScalars.test_main_tab_scalars | AssertionError: Error generating ping: Timed out after 60.0 seconds [task 2018-10-19T00:45:52.551Z] 00:45:52 INFO - Traceback (most recent call last): [task 2018-10-19T00:45:52.552Z] 00:45:52 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 159, in run [task 2018-10-19T00:45:52.552Z] 00:45:52 INFO - testMethod() [task 2018-10-19T00:45:52.552Z] 00:45:52 INFO - File "/builds/worker/checkouts/gecko/toolkit/components/telemetry/tests/marionette/tests/client/test_main_tab_scalars.py", line 40, in test_main_tab_scalars [task 2018-10-19T00:45:52.553Z] 00:45:52 INFO - ping = self.wait_for_ping(self.restart_browser, check_is_shutdown_ping) [task 2018-10-19T00:45:52.554Z] 00:45:52 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/telemetry_harness/testcase.py", line 70, in wait_for_pin 00:44:50 INFO - [Child 1346, Main Thread] WARNING: Fallback to BasicLayerManager: file /builds/worker/workspace/build/src/dom/ipc/TabChild.cpp, line 2839 [task 2018-10-19T00:44:50.776Z] 00:44:50 INFO - ++DOMWINDOW == 4 (0x7f70c9df7400) [pid = 1346] [serial = 4] [outer = 0x7f70dfa52a00] [task 2018-10-19T00:44:50.821Z] 00:44:50 INFO - ++DOMWINDOW == 5 (0x7f70c9960000) [pid = 1346] [serial = 5] [outer = 0x7f70dfa56c00] [task 2018-10-19T00:44:50.890Z] 00:44:50 INFO - ++DOMWINDOW == 6 (0x7f70c9963800) [pid = 1346] [serial = 6] [outer = 0x7f70dfa57800] [task 2018-10-19T00:44:50.912Z] 00:44:50 INFO - ++DOCSHELL 0x7f70c99b7000 == 4 [pid = 1346] [id = {a7edf63c-3a65-4da9-a96e-f28c350c3378}] [task 2018-10-19T00:44:50.913Z] 00:44:50 INFO - [Child 1346, Main Thread] WARNING: NS_ENSURE_TRUE(browserChrome) failed: file /builds/worker/workspace/build/src/docshell/base/nsDocShell.cpp, line 12587 [task 2018-10-19T00:44:50.914Z] 00:44:50 INFO - ++DOMWINDOW == 7 (0x7f70c994f200) [pid = 1346] [serial = 7] [outer = (nil)] [task 2018-10-19T00:44:50.930Z] 00:44:50 INFO - [Child 1346, Main Thread] WARNING: Fallback to BasicLayerManager: file /builds/worker/workspace/build/src/dom/ipc/TabChild.cpp, line 2839 [task 2018-10-19T00:44:50.947Z] 00:44:50 INFO - ++DOMWINDOW == 8 (0x7f70c9964c00) [pid = 1346] [serial = 8] [outer = 0x7f70c994f200] [task 2018-10-19T00:44:50.983Z] 00:44:50 INFO - ++DOMWINDOW == 9 (0x7f70c9d55c00) [pid = 1346] [serial = 9] [outer = 0x7f70dfa52a00] [task 2018-10-19T00:44:51.000Z] 00:44:50 INFO - ++DOMWINDOW == 10 (0x7f70c893d800) [pid = 1346] [serial = 10] [outer = 0x7f70dfa56c00] [task 2018-10-19T00:44:51.016Z] 00:44:51 INFO - ++DOMWINDOW == 11 (0x7f70c893e800) [pid = 1346] [serial = 11] [outer = 0x7f70dfa57800] [task 2018-10-19T00:44:51.037Z] 00:44:51 INFO - ++DOMWINDOW == 12 (0x7f70c8940000) [pid = 1346] [serial = 12] [outer = 0x7f70c994f200] [task 2018-10-19T00:44:51.317Z] 00:44:51 INFO - 1539909891308 Marionette DEBUG Waiting for startup tests... [task 2018-10-19T00:44:51.434Z] 00:44:51 INFO - 1539909891426 Marionette INFO Listening on port 2828 [task 2018-10-19T00:44:51.435Z] 00:44:51 INFO - 1539909891427 Marionette DEBUG Remote service is active [task 2018-10-19T00:44:51.533Z] 00:44:51 INFO - 1539909891522 Marionette DEBUG Accepted connection 0 from 127.0.0.1:42294 [task 2018-10-19T00:44:51.562Z] 00:44:51 INFO - 1539909891553 Marionette DEBUG Closed connection 0 [task 2018-10-19T00:44:51.564Z] 00:44:51 INFO - 1539909891557 Marionette DEBUG Accepted connection 1 from 127.0.0.1:42296 [task 2018-10-19T00:44:51.585Z] 00:44:51 INFO - 1539909891581 Marionette TRACE 1 -> [0,1,"WebDriver:NewSession",{}] [task 2018-10-19T00:44:51.889Z] 00:44:51 INFO - 1539909891881 Marionette DEBUG [2147483649] Frame script loaded [task 2018-10-19T00:44:51.930Z] 00:44:51 INFO - 1539909891917 Marionette DEBUG [2147483649] Frame script registered [task 2018-10-19T00:44:51.983Z] 00:44:51 INFO - 1539909891977 Marionette TRACE 1 <- [1,1,null,{"sessionId":"ba4cebb6-87c7-4c0a-be7d-b9611d4cf947","capabilities":{"browserName":"firefox","browserVersion":"64.0a ... /builds/worker/workspace/build/tmphG2fSJ.mozrunner","moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}] [task 2018-10-19T00:44:52.025Z] 00:44:52 INFO - 1539909892023 Marionette TRACE 1 -> [0,2,"Marionette:SetContext",{"value":"chrome"}] [task 2018-10-19T00:44:52.033Z] 00:44:52 INFO - 1539909892027 Marionette TRACE 1 <- [1,2,null,{"value":null}] [task 2018-10-19T00:44:52.036Z] 00:44:52 INFO - 1539909892032 Marionette TRACE 1 -> [0,3,"WebDriver:GetChromeWindowHandles",{}] [task 2018-10-19T00:44:52.037Z] 00:44:52 INFO - 1539909892035 Marionette TRACE 1 <- [1,3,null,["1"]] [task 2018-10-19T00:44:52.046Z] 00:44:52 INFO - 1539909892041 Marionette TRACE 1 -> [0,4,"WebDriver:GetChromeWindowHandle",{}] [task 2018-10-19T00:44:52.047Z] 00:44:52 INFO - 1539909892043 Marionette TRACE 1 <- [1,4,null,{"value":"1"}] [task 2018-10-19T00:44:52.055Z] 00:44:52 INFO - 1539909892050 Marionette TRACE 1 -> [0,5,"WebDriver:GetChromeWindowHandles",{}] [task 2018-10-19T00:44:52.058Z] 00:44:52 INFO - 1539909892053 Marionette TRACE 1 <- [1,5,null,["1"]] [task 2018-10-19T00:44:52.075Z] 00:44:52 INFO - 1539909892064 Marionette TRACE 1 -> [0,6,"WebDriver:SwitchToWindow",{"focus":true,"name":"1"}] [task 2018-10-19T00:44:52.077Z] 00:44:52 INFO - 1539909892068 Marionette TRACE 1 <- [1,6,null,{"value":null}] [task 2018-10-19T00:44:52.079Z] 00:44:52 INFO - 1539909892074 Marionette TRACE 1 -> [0,7,"WebDriver:GetChromeWindowHandle",{}] [task 2018-10-19T00:44:52.088Z] 00:44:52 INFO - 1539909892082 Marionette TRACE 1 <- [1,7,null,{"value":"1"}] [task 2018-10-19T00:44:52.091Z] 00:44:52 INFO - 1539909892086 Marionette TRACE 1 -> [0,8,"Marionette:GetContext",{}] [task 2018-10-19T00:44:52.100Z] 00:44:52 INFO - 1539909892093 Marionette TRACE 1 <- [1,8,null,{"value":"chrome"}] [task 2018-10-19T00:44:52.109Z] 00:44:52 INFO - 1539909892102 Marionette TRACE 1 -> [0,9,"Marionette:SetContext",{"value":"chrome"}] [task 2018-10-19T00:44:52.112Z] 00:44:52 INFO - 1539909892105 Marionette TRACE 1 <- [1,9,null,{"value":null}] [task 2018-10-19T00:44:52.128Z] 00:44:52 INFO - 1539909892119 Marionette TRACE 1 -> [0,10,"WebDriver:GetChromeWindowHandle",{}] [task 2018-10-19T00:44:52.131Z] 00:44:52 INFO - 1539909892121 Marionette TRACE 1 <- [1,10,null,{"value":"1"}] [task 2018-10-19T00:44:52.148Z] 00:44:52 INFO - 1539909892139 Marionette TRACE 1 -> [0,11,"Marionette:GetWindowType",{}] [task 2018-10-19T00:44:52.152Z] 00:44:52 INFO - 1539909892147 Marionette TRACE 1 <- [1,11,null,{"value":"navigator:browser"}] [task 2018-10-19T00:44:52.163Z] 00:44:52 INFO - 1539909892158 Marionette TRACE 1 -> [0,12,"WebDriver:GetChromeWindowHandles",{}] [task 2018-10-19T00:44:52.163Z] 00:44:52 INFO - 1539909892160 Marionette TRACE 1 <- [1,12,null,["1"]] [task 2018-10-19T00:44:52.172Z] 00:44:52 INFO - 1539909892167 Marionette TRACE 1 -> [0,13,"Marionette:GetContext",{}] [task 2018-10-19T00:44:52.172Z] 00:44:52 INFO - 1539909892168 Marionette TRACE 1 <- [1,13,null,{"value":"chrome"}] [task 2018-10-19T00:44:52.180Z] 00:44:52 INFO - 1539909892173 Marionette TRACE 1 -> [0,14,"Marionette:SetContext",{"value":"chrome"}] [task 2018-10-19T00:44:52.180Z] 00:44:52 INFO - 1539909892175 Marionette TRACE 1 <- [1,14,null,{"value":null}] [task 2018-10-19T00:44:52.216Z] 00:44:52 INFO - 1539909892206 Marionette TRACE 1 -> [0,15,"WebDriver:ExecuteScript",{"scriptTimeout":null,"newSandbox":true,"args":["1"],"filename":"venv/lib/python2.7/site-pack ... wWithId(Number(arguments[0]));\n return win.document.readyState == 'complete';","sandbox":"default","line":157}] [task 2018-10-19T00:44:52.224Z] 00:44:52 INFO - 1539909892220 Marionette TRACE 1 <- [1,15,null,{"value":true}] [task 2018-10-19T00:44:52.233Z] 00:44:52 INFO - 1539909892225 Marionette TRACE 1 -> [0,16,"Marionette:SetContext",{"value":"chrome"}] [task 2018-10-19T00:44:52.234Z] 00:44:52 INFO - 1539909892227 Marionette TRACE 1 <- [1,16,null,{"value":null}] [task 2018-10-19T00:44:52.234Z] 00:44:52 INFO - 1539909892230 Marionette TRACE 1 -> [0,17,"Marionette:SetContext",{"value":"chrome"}] [task 2018-10-19T00:44:52.244Z] 00:44:52 INFO - 1539909892236 Marionette TRACE 1 <- [1,17,null,{"value":null}] [task 2018-10-19T00:44:52.244Z] 00:44:52 INFO - 1539909892239 Marionette TRACE 1 -> [0,18,"WebDriver:SwitchToWindow",{"focus":true,"name":"1"}] [task 2018-10-19T00:44:52.246Z] 00:44:52 INFO - 1539909892242 Marionette TRACE 1 <- [1,18,null,{"value":null}] [task 2018-10-19T00:44:52.254Z] 00:44:52 INFO - 1539909892249 Marionette TRACE 1 -> [0,19,"WebDriver:GetChromeWindowHandle",{}] [task 2018-10-19T00:44:52.255Z] 00:44:52 INFO - 1539909892251 Marionette TRACE 1 <- [1,19,null,{"value":"1"}] [task 2018-10-19T00:44:52.263Z] 00:44:52 INFO - 1539909892256 Marionette TRACE 1 -> [0,20,"Marionette:GetContext",{}] [task 2018-10-19T00:44:52.264Z] 00:44:52 INFO - 1539909892258 Marionette TRACE 1 <- [1,20,null,{"value":"chrome"}] [task 2018-10-19T00:44:52.264Z] 00:44:52 INFO - 1539909892261 Marionette TRACE 1 -> [0,21,"Marionette:SetContext",{"value":"chrome"}] [task 2018-10-19T00:44:52.273Z] 00:44:52 INFO - 1539909892268 Marionette TRACE 1 <- [1,21,null,{"value":null}] [task 2018-10-19T00:44:52.273Z] 00:44:52 INFO - 1539909892271 Marionette TRACE 1 -> [0,22,"WebDriver:GetChromeWindowHandle",{}] [task 2018-10-19T00:44:52.277Z] 00:44:52 INFO - 1539909892275 Marionette TRACE 1 <- [1,22,null,{"value":"1"}] [task 2018-10-19T00:44:52.281Z] 00:44:52 INFO - 1539909892279 Marionette TRACE 1 -> [0,23,"Marionette:GetWindowType",{}] [task 2018-10-19T00:44:52.284Z] 00:44:52 INFO - 1539909892281 Marionette TRACE 1 <- [1,23,null,{"value":"navigator:browser"}] [task 2018-10-19T00:44:52.293Z] 00:44:52 INFO - 1539909892285 Marionette TRACE 1 -> [0,24,"WebDriver:GetChromeWindowHandles",{}] [task 2018-10-19T00:44:52.293Z] 00:44:52 INFO - 1539909892288 Marionette TRACE 1 <- [1,24,null,["1"]] [task 2018-10-19T00:44:52.294Z] 00:44:52 INFO - 1539909892291 Marionette TRACE 1 -> [0,25,"Marionette:GetContext",{}] [task 2018-10-19T00:44:52.298Z] 00:44:52 INFO - 1539909892295 Marionette TRACE 1 <- [1,25,null,{"value":"chrome"}] [task 2018-10-19T00:44:52.302Z] 00:44:52 INFO - 1539909892300 Marionette TRACE 1 -> [0,26,"Marionette:SetContext",{"value":"chrome"}] [task 2018-10-19T00:44:52.305Z] 00:44:52 INFO - 1539909892303 Marionette TRACE 1 <- [1,26,null,{"value":null}] [task 2018-10-19T00:44:52.313Z] 00:44:52 INFO - 1539909892308 Marionette TRACE 1 -> [0,27,"WebDriver:ExecuteScript",{"scriptTimeout":null,"newSandbox":true,"args":["1"],"filename":"venv/lib/python2.7/site-pack ... wWithId(Number(arguments[0]));\n return win.document.readyState == 'complete';","sandbox":"default","line":157}] [task 2018-10-19T00:44:52.329Z] 00:44:52 INFO - 1539909892321 Marionette TRACE 1 <- [1,27,null,{"value":true}] [task 2018-10-19T00:44:52.347Z] 00:44:52 INFO - 1539909892336 Marionette TRACE 1 -> [0,28,"Marionette:SetContext",{"value":"chrome"}] [task 2018-10-19T00:44:52.348Z] 00:44:52 INFO - 1539909892340 Marionette TRACE 1 <- [1,28,null,{"value":null}] [task 2018-10-19T00:44:52.384Z] 00:44:52 INFO - 1539909892381 Marionette TRACE 1 -> [0,29,"Marionette:SetContext",{"value":"chrome"}] [task 2018-10-19T00:44:52.386Z] 00:44:52 INFO - 1539909892384 Marionette TRACE 1 <- [1,29,null,{"value":null}] [task 2018-10-19T00:44:52.791Z] 00:44:52 INFO - Couldn't convert chrome URL: chrome://branding/locale/brand.properties [task 2018-10-19T00:44:57.936Z] 00:44:57 INFO - --DOCSHELL 0x7f91ef5c8800 == 7 [pid = 1024] [id = {548f446e-ddc7-4f2b-8368-0efdab7f4758}] [task 2018-10-19T00:45:02.005Z] 00:45:02 INFO - --DOMWINDOW == 24 (0x7f91f6b99c00) [pid = 1024] [serial = 4] [outer = (nil)] [url = about:blank] [task 2018-10-19T00:45:02.007Z] 00:45:02 INFO - --DOMWINDOW == 23 (0x7f91eaddf400) [pid = 1024] [serial = 12] [outer = (nil)] [url = about:blank] [task 2018-10-19T00:45:02.007Z] 00:45:02 INFO - --DOMWINDOW == 22 (0x7f91eadde800) [pid = 1024] [serial = 11] [outer = (nil)] [url = about:blank] [task 2018-10-19T00:45:02.008Z] 00:45:02 INFO - --DOMWINDOW == 21 (0x7f91eade0800) [pid = 1024] [serial = 15] [outer = (nil)] [url = about:blank] [task 2018-10-19T00:45:02.008Z] 00:45:02 INFO - --DOMWINDOW == 20 (0x7f91eade0000) [pid = 1024] [serial = 14] [outer = (nil)] [url = about:blank] [task 2018-10-19T00:45:02.009Z] 00:45:02 INFO - --DOMWINDOW == 19 (0x7f91eb9abc00) [pid = 1024] [serial = 18] [outer = (nil)] [url = about:blank] [task 2018-10-19T00:45:02.009Z] 00:45:02 INFO - --DOMWINDOW == 18 (0x7f91eb9ab000) [pid = 1024] [serial = 17] [outer = (nil)] [url = about:blank] [task 2018-10-19T00:45:02.010Z] 00:45:02 INFO - --DOMWINDOW == 17 (0x7f91eb9adc00) [pid = 1024] [serial = 21] [outer = (nil)] [url = about:blank] [task 2018-10-19T00:45:02.010Z] 00:45:02 INFO - --DOMWINDOW == 16 (0x7f91eb9acc00) [pid = 1024] [serial = 20] [outer = (nil)] [url = about:blank] [task 2018-10-19T00:45:03.921Z] 00:45:03 INFO - --DOMWINDOW == 3 (0x7fe83795e800) [pid = 1286] [serial = 2] [outer = (nil)] [url = about:blank] [task 2018-10-19T00:45:03.922Z] 00:45:03 INFO - --DOMWINDOW == 2 (0x7fe837ad0000) [pid = 1286] [serial = 3] [outer = (nil)] [url = about:blank] [task 2018-10-19T00:45:04.407Z] 00:45:04 INFO - --DOMWINDOW == 15 (0x7f91efce1e00) [pid = 1024] [serial = 7] [outer = (nil)] [url = about:blank] [task 2018-10-19T00:45:05.383Z] 00:45:05 INFO - --DOMWINDOW == 11 (0x7f70c9df7400) [pid = 1346] [serial = 4] [outer = (nil)] [url = about:blank] [task 2018-10-19T00:45:05.384Z] 00:45:05 INFO - --DOMWINDOW == 10 (0x7f70c9960000) [pid = 1346] [serial = 5] [outer = (nil)] [url = about:blank] [task 2018-10-19T00:45:05.385Z] 00:45:05 INFO - --DOMWINDOW == 9 (0x7f70c9964c00) [pid = 1346] [serial = 8] [outer = (nil)] [url = about:blank] [task 2018-10-19T00:45:05.385Z] 00:45:05 INFO - --DOMWINDOW == 8 (0x7f70c9963800) [pid = 1346] [serial = 6] [outer = (nil)] [url = about:blank] [task 2018-10-19T00:45:07.321Z] 00:45:07 INFO - --DOMWINDOW == 14 (0x7f91ef205800) [pid = 1024] [serial = 8] [outer = (nil)] [url = about:blank] [task 2018-10-19T00:45:08.935Z] 00:45:08 INFO - [Parent 1024, StreamTrans #43] WARNING: 'NS_FAILED(rv)', file /builds/worker/workspace/build/src/modules/libjar/nsJARChannel.cpp, line 419 [task 2018-10-19T00:45:08.935Z] 00:45:08 INFO - [Parent 1024, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012: file /builds/worker/workspace/build/src/modules/libjar/nsJARChannel.cpp, line 1127 [task 2018-10-19T00:45:52.403Z] 00:45:52 INFO - 1539909952401 Marionette TRACE 1 -> [0,30,"Marionette:GetContext",{}] [task 2018-10-19T00:45:52.408Z] 00:45:52 INFO - 1539909952404 Marionette TRACE 1 <- [1,30,null,{"value":"chrome"}] [task 2018-10-19T00:45:52.416Z] 00:45:52 INFO - 1539909952412 Marionette TRACE 1 -> [0,31,"Marionette:SetContext",{"value":"chrome"}] [task 2018-10-19T00:45:52.418Z] 00:45:52 INFO - 1539909952414 Marionette TRACE 1 <- [1,31,null,{"value":null}] [task 2018-10-19T00:45:52.426Z] 00:45:52 INFO - 1539909952419 Marionette TRACE 1 -> [0,32,"WebDriver:TakeScreenshot",{"highlights":null,"full":true,"hash":false,"id":null,"scroll":true}] [task 2018-10-19T00:45:52.488Z] 00:45:52 INFO - 1539909952484 Marionette TRACE 1 <- [1,32,null,{"value":"iVBORw0KGgoAAAANSUhEUgAABQAAAAQQCAYAAAC9RfbYAAAgAElEQVR4nOzdzW9c92HucS8L9P8IkAJFd76LFOgmS2+Lu8zCEJfu3Rha ... QAAACAMQEIAAAAAGMCEAAAAADGBCAAAAAAjAlAAAAAABgTgAAAAAAwJgABAAAAYEwAAgAAAMCYAAQAAACAMQEIAAAAAGMB9MPMXXzG24QAAAAASUVORK5CYII="}] [task 2018-10-19T00:45:52.493Z] 00:45:52 INFO - 1539909952490 Marionette TRACE 1 -> [0,33,"Marionette:SetContext",{"value":"chrome"}] [task 2018-10-19T00:45:52.496Z] 00:45:52 INFO - 1539909952493 Marionette TRACE 1 <- [1,33,null,{"value":null}] [task 2018-10-19T00:45:52.501Z] 00:45:52 INFO - 1539909952498 Marionette TRACE 1 -> [0,34,"Marionette:GetContext",{}] [task 2018-10-19T00:45:52.503Z] 00:45:52 INFO - 1539909952500 Marionette TRACE 1 <- [1,34,null,{"value":"chrome"}] [task 2018-10-19T00:45:52.520Z] 00:45:52 INFO - 1539909952510 Marionette TRACE 1 -> [0,35,"Marionette:SetContext",{"value":"content"}] [task 2018-10-19T00:45:52.521Z] 00:45:52 INFO - 1539909952512 Marionette TRACE 1 <- [1,35,null,{"value":null}] [task 2018-10-19T00:45:52.521Z] 00:45:52 INFO - 1539909952515 Marionette TRACE 1 -> [0,36,"WebDriver:GetPageSource",{}] [task 2018-10-19T00:45:52.550Z] 00:45:52 INFO - TEST-UNEXPECTED-FAIL | ../../checkouts/gecko/toolkit/components/telemetry/tests/marionette/tests/client/test_main_tab_scalars.py TestMainTabScalars.test_main_tab_scalars | AssertionError: Error generating ping: Timed out after 60.0 seconds [task 2018-10-19T00:45:52.551Z] 00:45:52 INFO - Traceback (most recent call last): [task 2018-10-19T00:45:52.552Z] 00:45:52 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 159, in run [task 2018-10-19T00:45:52.552Z] 00:45:52 INFO - testMethod() [task 2018-10-19T00:45:52.552Z] 00:45:52 INFO - File "/builds/worker/checkouts/gecko/toolkit/components/telemetry/tests/marionette/tests/client/test_main_tab_scalars.py", line 40, in test_main_tab_scalars [task 2018-10-19T00:45:52.553Z] 00:45:52 INFO - ping = self.wait_for_ping(self.restart_browser, check_is_shutdown_ping) [task 2018-10-19T00:45:52.554Z] 00:45:52 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/telemetry_harness/testcase.py", line 70, in wait_for_ping [task 2018-10-19T00:45:52.554Z] 00:45:52 INFO - self.fail('Error generating ping: {}'.format(e.message)) [task 2018-10-19T00:45:52.554Z] 00:45:52 INFO - TEST-INFO took 92783msg [task 2018-10-19T00:45:52.554Z] 00:45:52 INFO - self.fail('Error generating ping: {}'.format(e.message)) [task 2018-10-19T00:45:52.554Z] 00:45:52 INFO - TEST-INFO took 92783ms
Hey Raphael, is this related to bug 1382854 and bug 1500185?
Flags: needinfo?(rpierzina)
Assignee: nobody → rpierzina
Flags: needinfo?(rpierzina)
Do you think increasing the timeout to 120s might help with these intermittent failures? https://searchfox.org/mozilla-central/source/toolkit/components/telemetry/tests/marionette/harness/telemetry_harness/testcase.py#68
Flags: needinfo?(alessio.placitelli)
Mh, I'm not sure. To be sure we'd need logs from Telemetry. I find it kind of surprising that no logs seem to be present on treeherder: we should at the very least see a few lines from TelemetryController and TelemetrySend, before the failure.
Flags: needinfo?(alessio.placitelli)
Priority: P5 → P1
Blocks: 1504648
Attachment #9021881 - Attachment is obsolete: true
Pushed by rpierzina@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/1b11540e60c7 Refactor TelemetryTestCase and add logging; r=Dexter,whimboo
Status: NEW → RESOLVED
Closed: 7 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla65
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: