Filed by: apavel [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=320854390&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/fwcRxqXlRaaEDPjyJ1T72w/runs/0/artifacts/public/logs/live_backing.log
[task 2020-11-05T17:59:15.491Z] 17:59:15 INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_click.py TestClickNavigation.test_click_no_link
[task 2020-11-05T17:59:15.491Z] 17:59:15 INFO - 1604599155488 Marionette DEBUG 200 <- [1,25,null,{"value":null}]
[task 2020-11-05T17:59:15.491Z] 17:59:15 INFO - 1604599155489 Marionette DEBUG Closed connection 200
[task 2020-11-05T17:59:15.493Z] 17:59:15 INFO - 1604599155490 Marionette DEBUG Accepted connection 201 from 127.0.0.1:50338
[task 2020-11-05T17:59:15.493Z] 17:59:15 INFO - 1604599155491 Marionette DEBUG 201 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2020-11-05T17:59:15.495Z] 17:59:15 INFO - 1604599155492 Marionette TRACE [17] Frame script loaded
[task 2020-11-05T17:59:15.495Z] 17:59:15 INFO - 1604599155493 Marionette DEBUG 201 <- [1,1,null,{"sessionId":"70cec750-1ada-4ea4-a32d-326f7cb54210","capabilities":{"browserName":"firefox","browserVersion":"84.0a ... p\\tmps_r_om.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2020-11-05T17:59:15.497Z] 17:59:15 INFO - 1604599155494 Marionette DEBUG 201 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2020-11-05T17:59:15.497Z] 17:59:15 INFO - 1604599155494 Marionette DEBUG 201 <- [1,2,null,{"value":null}]
[task 2020-11-05T17:59:15.497Z] 17:59:15 INFO - 1604599155495 Marionette DEBUG 201 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2020-11-05T17:59:15.497Z] 17:59:15 INFO - 1604599155495 Marionette DEBUG 201 <- [1,3,null,{"value":null}]
[task 2020-11-05T17:59:15.499Z] 17:59:15 INFO - 1604599155496 Marionette DEBUG 201 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2020-11-05T17:59:15.499Z] 17:59:15 INFO - 1604599155496 Marionette DEBUG 201 <- [1,4,null,{"value":null}]
[task 2020-11-05T17:59:15.499Z] 17:59:15 INFO - 1604599155497 Marionette DEBUG 201 -> [0,5,"WebDriver:GetChromeWindowHandle",{}]
[task 2020-11-05T17:59:15.499Z] 17:59:15 INFO - 1604599155497 Marionette DEBUG 201 <- [1,5,null,{"value":"6"}]
[task 2020-11-05T17:59:15.499Z] 17:59:15 INFO - 1604599155497 Marionette DEBUG 201 -> [0,6,"WebDriver:GetChromeWindowHandles",{}]
[task 2020-11-05T17:59:15.500Z] 17:59:15 INFO - 1604599155498 Marionette DEBUG 201 <- [1,6,null,["6"]]
[task 2020-11-05T17:59:15.502Z] 17:59:15 INFO - 1604599155498 Marionette DEBUG 201 -> [0,7,"WebDriver:GetWindowHandle",{}]
[task 2020-11-05T17:59:15.502Z] 17:59:15 INFO - 1604599155498 Marionette DEBUG 201 <- [1,7,null,{"value":"17"}]
[task 2020-11-05T17:59:15.502Z] 17:59:15 INFO - 1604599155499 Marionette DEBUG 201 -> [0,8,"WebDriver:GetWindowHandles",{}]
[task 2020-11-05T17:59:15.502Z] 17:59:15 INFO - 1604599155499 Marionette DEBUG 201 <- [1,8,null,["17"]]
[task 2020-11-05T17:59:15.502Z] 17:59:15 INFO - 1604599155500 Marionette DEBUG 201 -> [0,9,"WebDriver:GetWindowHandles",{}]
[task 2020-11-05T17:59:15.502Z] 17:59:15 INFO - 1604599155500 Marionette DEBUG 201 <- [1,9,null,["17"]]
[task 2020-11-05T17:59:15.503Z] 17:59:15 INFO - 1604599155500 Marionette DEBUG 201 -> [0,10,"WebDriver:NewWindow",{"type":"tab","focus":false,"private":false}]
[task 2020-11-05T17:59:15.505Z] 17:59:15 INFO - 1604599155503 Marionette TRACE Received DOM event TabOpen for [object XULElement]
[task 2020-11-05T17:59:15.524Z] 17:59:15 INFO - 1604599155521 Marionette TRACE [160] Frame script loaded
[task 2020-11-05T17:59:15.542Z] 17:59:15 INFO - 1604599155534 Marionette DEBUG 201 <- [1,10,null,{"handle":"160","type":"tab"}]
[task 2020-11-05T17:59:15.544Z] 17:59:15 INFO - DEBUG: Adding blocker ContentParent: id=143c68b7000 for phase xpcom-will-shutdown
[task 2020-11-05T17:59:15.544Z] 17:59:15 INFO - DEBUG: Adding blocker ContentParent: id=143c68b7000 for phase profile-before-change
[task 2020-11-05T17:59:15.549Z] 17:59:15 INFO - 1604599155546 Marionette DEBUG 201 -> [0,11,"WebDriver:GetWindowHandles",{}]
[task 2020-11-05T17:59:15.549Z] 17:59:15 INFO - 1604599155546 Marionette DEBUG 201 <- [1,11,null,["17","160"]]
[task 2020-11-05T17:59:15.549Z] 17:59:15 INFO - 1604599155547 Marionette DEBUG 201 -> [0,12,"WebDriver:GetWindowHandles",{}]
[task 2020-11-05T17:59:15.549Z] 17:59:15 INFO - 1604599155547 Marionette DEBUG 201 <- [1,12,null,["17","160"]]
[task 2020-11-05T17:59:15.551Z] 17:59:15 INFO - 1604599155550 Marionette DEBUG 201 -> [0,13,"WebDriver:SwitchToWindow",{"handle":"160","focus":true}]
[task 2020-11-05T17:59:15.561Z] 17:59:15 INFO - 1604599155556 Marionette TRACE Received DOM event TabSelect for [object XULElement]
[task 2020-11-05T17:59:15.566Z] 17:59:15 INFO - 1604599155563 Marionette DEBUG 201 <- [1,13,null,{"value":null}]
[task 2020-11-05T17:59:15.566Z] 17:59:15 INFO - 1604599155563 Marionette DEBUG 201 -> [0,14,"WebDriver:Navigate",{"url":"http://127.0.0.1:49874/clicks.html"}]
[task 2020-11-05T17:59:15.568Z] 17:59:15 INFO - 1604599155566 Marionette TRACE [160] MarionetteCommands actor created for window id 92341796865
[task 2020-11-05T17:59:15.587Z] 17:59:15 INFO - 1604599155580 Marionette TRACE [160] Frame script loaded
[task 2020-11-05T17:59:15.587Z] 17:59:15 INFO - 1604599155581 Marionette TRACE Detected remoteness change. New browsing context: 160
[task 2020-11-05T17:59:15.587Z] 17:59:15 INFO - 1604599155581 Marionette TRACE [160] MarionetteEvents actor created for window id 219
[task 2020-11-05T17:59:15.597Z] 17:59:15 INFO - 1604599155593 Marionette TRACE Received event beforeunload for about:blank
[task 2020-11-05T17:59:15.599Z] 17:59:15 INFO - 1604599155596 Marionette TRACE Received event pagehide for about:blank
[task 2020-11-05T17:59:15.601Z] 17:59:15 INFO - 1604599155599 Marionette TRACE [160] MarionetteEvents actor created for window id 92341796865
[task 2020-11-05T17:59:15.601Z] 17:59:15 INFO - 1604599155600 Marionette TRACE [160] MarionetteEvents actor created for window id 6442450974
[task 2020-11-05T17:59:15.603Z] 17:59:15 INFO - 1604599155601 Marionette TRACE [160] Frame script unloaded
[task 2020-11-05T17:59:15.613Z] 17:59:15 INFO - 1604599155612 Marionette TRACE Received event beforeunload for about:blank
[task 2020-11-05T17:59:15.613Z] 17:59:15 INFO - 1604599155612 Marionette TRACE Received event DOMContentLoaded for http://127.0.0.1:49874/clicks.html
[task 2020-11-05T17:59:15.615Z] 17:59:15 INFO - 1604599155614 Marionette TRACE Received event pageshow for http://127.0.0.1:49874/clicks.html
[task 2020-11-05T17:59:15.615Z] 17:59:15 INFO - 1604599155614 Marionette TRACE Received event pagehide for about:blank
[task 2020-11-05T17:59:26.139Z] 17:59:26 INFO - DEBUG: Adding blocker SessionFile: Finish writing Session Restore data for phase profile-before-change
[task 2020-11-05T17:59:26.139Z] 17:59:26 INFO - DEBUG: Completed blocker SessionFile: Finish writing Session Restore data for phase profile-before-change
[task 2020-11-05T17:59:34.817Z] 17:59:34 INFO - DEBUG: Adding blocker JSON store: writing data for phase profile-before-change
[task 2020-11-05T17:59:41.144Z] 17:59:41 INFO - DEBUG: Adding blocker SessionFile: Finish writing Session Restore data for phase profile-before-change
[task 2020-11-05T17:59:41.146Z] 17:59:41 INFO - DEBUG: Completed blocker SessionFile: Finish writing Session Restore data for phase profile-before-change
[task 2020-11-05T18:04:15.578Z] 18:04:15 INFO - 1604599455572 Marionette DEBUG 201 <- [1,14,{"error":"timeout","message":"","stacktrace":"WebDriverError@chrome://marionette/content/error.js:181:5\nTimeoutError@chrome://marionette/content/error.js:450:5\nbail@chrome://marionette/content/sync.js:220:19\n"},null]
[task 2020-11-05T18:04:15.578Z] 18:04:15 INFO - 1604599455574 Marionette DEBUG 201 -> [0,15,"Marionette:GetContext",{}]
[task 2020-11-05T18:04:15.578Z] 18:04:15 INFO - 1604599455574 Marionette DEBUG 201 <- [1,15,null,{"value":"content"}]
[task 2020-11-05T18:04:15.579Z] 18:04:15 INFO - 1604599455575 Marionette DEBUG 201 -> [0,16,"Marionette:SetContext",{"value":"chrome"}]
[task 2020-11-05T18:04:15.579Z] 18:04:15 INFO - 1604599455575 Marionette DEBUG 201 <- [1,16,null,{"value":null}]
[task 2020-11-05T18:04:15.579Z] 18:04:15 INFO - 1604599455576 Marionette DEBUG 201 -> [0,17,"WebDriver:TakeScreenshot",{"full":true,"hash":false,"id":null,"scroll":true}]
[task 2020-11-05T18:04:15.579Z] 18:04:15 INFO - 1604599455576 Marionette TRACE [6] MarionetteCommands actor created for window id 2
[task 2020-11-05T18:04:15.658Z] 18:04:15 INFO - 1604599455649 Marionette DEBUG 201 <- [1,17,null,{"value":"iVBORw0KGgoAAAANSUhEUgAABQAAAAQHCAYAAACjlsT7AAAgAElEQVR4nOzdf5Cc9X0n+P5z65a6orbKIcMfF+7sP7QLLuTaSrrO3jXh ... gmAAIAAABAMAEQAAAAAIIJgAAAAAAQTAAEAAAAgGACIAAAAAAEEwABAAAAIJgACAAAAADBBEAAAAAACCYAAgAAAECw/wO+p7y/KRMtEgAAAABJRU5ErkJggg=="}]
[task 2020-11-05T18:04:15.658Z] 18:04:15 INFO - 1604599455651 Marionette DEBUG 201 -> [0,18,"Marionette:SetContext",{"value":"content"}]
[task 2020-11-05T18:04:15.659Z] 18:04:15 INFO - 1604599455651 Marionette DEBUG 201 <- [1,18,null,{"value":null}]
[task 2020-11-05T18:04:15.659Z] 18:04:15 INFO - 1604599455651 Marionette DEBUG 201 -> [0,19,"Marionette:GetContext",{}]
[task 2020-11-05T18:04:15.660Z] 18:04:15 INFO - 1604599455652 Marionette DEBUG 201 <- [1,19,null,{"value":"content"}]
[task 2020-11-05T18:04:15.660Z] 18:04:15 INFO - 1604599455652 Marionette DEBUG 201 -> [0,20,"Marionette:SetContext",{"value":"content"}]
[task 2020-11-05T18:04:15.660Z] 18:04:15 INFO - 1604599455652 Marionette DEBUG 201 <- [1,20,null,{"value":null}]
[task 2020-11-05T18:04:15.660Z] 18:04:15 INFO - 1604599455653 Marionette DEBUG 201 -> [0,21,"WebDriver:GetPageSource",{}]
[task 2020-11-05T18:04:15.661Z] 18:04:15 INFO - 1604599455654 Marionette TRACE [160] MarionetteCommands actor created for window id 6442450974
[task 2020-11-05T18:04:15.661Z] 18:04:15 INFO - 1604599455655 Marionette DEBUG 201 <- [1,21,null,{"value":"<html><head>\n <!-- This Source Code Form is subject to the terms of the Mozilla Public\n - License ... <a id=\"overflowLink\" href=\"test.html\">looooooooooong short looooooooooong</a>\n </p>\n</div>\n\n\n\n</body></html>"}]
[task 2020-11-05T18:04:15.661Z] 18:04:15 INFO - 1604599455656 Marionette DEBUG 201 -> [0,22,"Marionette:SetContext",{"value":"content"}]
[task 2020-11-05T18:04:15.661Z] 18:04:15 INFO - 1604599455656 Marionette DEBUG 201 <- [1,22,null,{"value":null}]
[task 2020-11-05T18:04:15.662Z] 18:04:15 ERROR - TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_click.py TestClickNavigation.test_click_no_link | TimeoutException:
[task 2020-11-05T18:04:15.662Z] 18:04:15 INFO - stacktrace:
[task 2020-11-05T18:04:15.662Z] 18:04:15 INFO - WebDriverError@chrome://marionette/content/error.js:181:5
[task 2020-11-05T18:04:15.663Z] 18:04:15 INFO - TimeoutError@chrome://marionette/content/error.js:450:5
[task 2020-11-05T18:04:15.663Z] 18:04:15 INFO - bail@chrome://marionette/content/sync.js:220:19
[task 2020-11-05T18:04:15.663Z] 18:04:15 INFO - Traceback (most recent call last):
[task 2020-11-05T18:04:15.663Z] 18:04:15 INFO - File "C:\Users\task_1604598625\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 195, in run
[task 2020-11-05T18:04:15.663Z] 18:04:15 INFO - self.setUp()
[task 2020-11-05T18:04:15.663Z] 18:04:15 INFO - File "C:\Users\task_1604598625\build\tests\marionette\tests\testing\marionette\harness\marionette_harness\tests\unit\test_click.py", line 486, in setUp
[task 2020-11-05T18:04:15.663Z] 18:04:15 INFO - self.marionette.navigate(self.test_page)
[task 2020-11-05T18:04:15.663Z] 18:04:15 INFO - File "C:\Users\task_1604598625\build\venv\lib\site-packages\marionette_driver\marionette.py", line 1501, in navigate
[task 2020-11-05T18:04:15.664Z] 18:04:15 INFO - self._send_message("WebDriver:Navigate", {"url": url})
[task 2020-11-05T18:04:15.664Z] 18:04:15 INFO - File "C:\Users\task_1604598625\build\venv\lib\site-packages\marionette_driver\decorators.py", line 27, in _
[task 2020-11-05T18:04:15.664Z] 18:04:15 INFO - return func(*args, **kwargs)
[task 2020-11-05T18:04:15.665Z] 18:04:15 INFO - File "C:\Users\task_1604598625\build\venv\lib\site-packages\marionette_driver\marionette.py", line 625, in _send_message
[task 2020-11-05T18:04:15.665Z] 18:04:15 INFO - self._handle_error(err)
[task 2020-11-05T18:04:15.665Z] 18:04:15 INFO - File "C:\Users\task_1604598625\build\venv\lib\site-packages\marionette_driver\marionette.py", line 647, in _handle_error
[task 2020-11-05T18:04:15.665Z] 18:04:15 INFO - raise errors.lookup(error)(message, stacktrace=stacktrace)
[task 2020-11-05T18:04:15.665Z] 18:04:15 INFO - TEST-INFO took 300167ms```
Description
•