Filed by: ccozmuta [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=375095393&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/aWrGEKy1T_iRc-aqNuS07w/runs/0/artifacts/public/logs/live_backing.log
[task 2022-04-20T04:06:00.746Z] 04:06:00 INFO - TEST-START | telemetry/marionette/tests/client/test_deletion_request_ping.py TestDeletionRequestPing.test_deletion_request_ping_across_sessions
[task 2022-04-20T04:06:00.747Z] 04:06:00 INFO - 1650427560747 Marionette DEBUG Accepted connection 2 from 127.0.0.1:49816
[task 2022-04-20T04:06:00.772Z] 04:06:00 INFO - 1650427560774 Marionette DEBUG 2 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2022-04-20T04:06:00.777Z] 04:06:00 INFO - 1650427560777 RemoteAgent TRACE [24] Document already finished loading: about:blank
[task 2022-04-20T04:06:00.778Z] 04:06:00 INFO - 1650427560778 Marionette DEBUG 2 <- [1,1,null,{"sessionId":"42043fc7-c5ba-4d53-8b61-13aa36abc2c2","capabilities":{"browserName":"firefox","browserVersion":"101.0 ... 9.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"proxy":{}}}]
[task 2022-04-20T04:06:00.780Z] 04:06:00 INFO - 1650427560780 Marionette DEBUG 2 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2022-04-20T04:06:00.780Z] 04:06:00 INFO - 1650427560781 Marionette DEBUG 2 <- [1,2,null,{"value":null}]
[task 2022-04-20T04:06:00.782Z] 04:06:00 INFO - 1650427560782 Marionette DEBUG 2 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2022-04-20T04:06:00.782Z] 04:06:00 INFO - 1650427560782 Marionette DEBUG 2 <- [1,3,null,{"value":null}]
[task 2022-04-20T04:06:00.783Z] 04:06:00 INFO - 1650427560784 Marionette DEBUG 2 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2022-04-20T04:06:00.784Z] 04:06:00 INFO - 1650427560784 Marionette DEBUG 2 <- [1,4,null,{"value":null}]
[task 2022-04-20T04:06:00.785Z] 04:06:00 INFO - 1650427560786 Marionette DEBUG 2 -> [0,5,"Marionette:GetContext",{}]
[task 2022-04-20T04:06:00.786Z] 04:06:00 INFO - 1650427560786 Marionette DEBUG 2 <- [1,5,null,{"value":"content"}]
[task 2022-04-20T04:06:00.787Z] 04:06:00 INFO - 1650427560787 Marionette DEBUG 2 -> [0,6,"Marionette:SetContext",{"value":"chrome"}]
[task 2022-04-20T04:06:00.787Z] 04:06:00 INFO - 1650427560787 Marionette DEBUG 2 <- [1,6,null,{"value":null}]
[task 2022-04-20T04:06:00.789Z] 04:06:00 INFO - 1650427560789 Marionette DEBUG 2 -> [0,7,"WebDriver:GetWindowHandle",{}]
[task 2022-04-20T04:06:00.789Z] 04:06:00 INFO - 1650427560789 Marionette DEBUG 2 <- [1,7,null,{"value":"4b5b4d7b-30d7-40f9-855b-78496b9d74ea"}]
[task 2022-04-20T04:06:00.790Z] 04:06:00 INFO - 1650427560790 Marionette DEBUG 2 -> [0,8,"Marionette:SetContext",{"value":"content"}]
[task 2022-04-20T04:06:00.790Z] 04:06:00 INFO - 1650427560791 Marionette DEBUG 2 <- [1,8,null,{"value":null}]
[task 2022-04-20T04:06:00.792Z] 04:06:00 INFO - 1650427560792 Marionette DEBUG 2 -> [0,9,"Marionette:GetContext",{}]
[task 2022-04-20T04:06:00.793Z] 04:06:00 INFO - 1650427560793 Marionette DEBUG 2 <- [1,9,null,{"value":"content"}]
[task 2022-04-20T04:06:00.794Z] 04:06:00 INFO - 1650427560794 Marionette DEBUG 2 -> [0,10,"Marionette:SetContext",{"value":"chrome"}]
[task 2022-04-20T04:06:00.794Z] 04:06:00 INFO - 1650427560794 Marionette DEBUG 2 <- [1,10,null,{"value":null}]
<...>
[task 2022-04-20T04:06:06.862Z] 04:06:06 INFO - 1650427566863 Marionette DEBUG 2 -> [0,23,"Marionette:SetContext",{"value":"content"}]
[task 2022-04-20T04:06:06.862Z] 04:06:06 INFO - 1650427566863 Marionette DEBUG 2 <- [1,23,null,{"value":null}]
[task 2022-04-20T04:06:06.862Z] 04:06:06 INFO - 1650427566864 Marionette DEBUG 2 -> [0,24,"WebDriver:GetPageSource",{}]
[task 2022-04-20T04:06:06.862Z] 04:06:06 INFO - 1650427566868 Marionette TRACE [30] MarionetteCommands actor created for window id 4294967297
[task 2022-04-20T04:06:06.862Z] 04:06:06 INFO - 1650427566870 Marionette DEBUG 2 <- [1,24,null,{"value":"<html><head></head><body></body></html>"}]
[task 2022-04-20T04:06:06.862Z] 04:06:06 INFO - 1650427566871 Marionette DEBUG 2 -> [0,25,"Marionette:SetContext",{"value":"content"}]
[task 2022-04-20T04:06:06.862Z] 04:06:06 INFO - 1650427566871 Marionette DEBUG 2 <- [1,25,null,{"value":null}]
[task 2022-04-20T04:06:06.893Z] 04:06:06 INFO - TEST-UNEXPECTED-ERROR | telemetry/marionette/tests/client/test_deletion_request_ping.py TestDeletionRequestPing.test_deletion_request_ping_across_sessions | marionette_driver.errors.ScriptTimeoutException: Timed out after 1000 ms
[task 2022-04-20T04:06:06.893Z] 04:06:06 INFO - stacktrace:
[task 2022-04-20T04:06:06.893Z] 04:06:06 INFO - WebDriverError@chrome://remote/content/shared/webdriver/Errors.jsm:183:5
[task 2022-04-20T04:06:06.893Z] 04:06:06 INFO - ScriptTimeoutError@chrome://remote/content/shared/webdriver/Errors.jsm:445:5
[task 2022-04-20T04:06:06.893Z] 04:06:06 INFO - evaluate.sandbox/timeoutPromise</scriptTimeoutID<@chrome://remote/content/marionette/evaluate.js:128:16
[task 2022-04-20T04:06:06.893Z] 04:06:06 INFO - notify@resource://gre/modules/Timer.jsm:62:17
[task 2022-04-20T04:06:06.893Z] 04:06:06 INFO - Traceback (most recent call last):
[task 2022-04-20T04:06:06.893Z] 04:06:06 INFO - File "Z:\task_165042694587490\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 202, in run
[task 2022-04-20T04:06:06.893Z] 04:06:06 INFO - testMethod()
[task 2022-04-20T04:06:10.409Z] 04:06:06 INFO - File "Z:\task_165042694587490\build\tests\telemetry\marionette\tests\client\test_deletion_request_ping.py", line 55, in test_deletion_request_ping_across_sessions
[task 2022-04-20T04:06:10.409Z] 04:06:06 INFO - return self.marionette.execute_async_script(
[task 2022-04-20T04:06:10.409Z] 04:06:06 INFO - File "Z:\task_165042694587490\build\venv\lib\site-packages\marionette_driver\marionette.py", line 1763, in execute_async_script
[task 2022-04-20T04:06:10.409Z] 04:06:06 INFO - rv = self._send_message("WebDriver:ExecuteAsyncScript", body, key="value")
[task 2022-04-20T04:06:10.409Z] 04:06:06 INFO - File "Z:\task_165042694587490\build\venv\lib\site-packages\marionette_driver\decorators.py", line 27, in _
[task 2022-04-20T04:06:10.409Z] 04:06:06 INFO - return func(*args, **kwargs)
[task 2022-04-20T04:06:10.409Z] 04:06:06 INFO - File "Z:\task_165042694587490\build\venv\lib\site-packages\marionette_driver\marionette.py", line 668, in _send_message
[task 2022-04-20T04:06:10.409Z] 04:06:06 INFO - self._handle_error(err)
[task 2022-04-20T04:06:10.409Z] 04:06:06 INFO - File "Z:\task_165042694587490\build\venv\lib\site-packages\marionette_driver\marionette.py", line 680, in _handle_error
[task 2022-04-20T04:06:10.409Z] 04:06:06 INFO - raise errors.lookup(error)(message, stacktrace=stacktrace)
[task 2022-04-20T04:06:10.409Z] 04:06:06 INFO - TEST-INFO took 6117ms
[task 2022-04-20T04:06:10.409Z] 04:06:06 INFO - 1650427566900 Marionette DEBUG 2 -> [0,26,"Marionette:GetContext",{}]
[task 2022-04-20T04:06:10.409Z] 04:06:06 INFO - 1650427566900 Marionette DEBUG 2 <- [1,26,null,{"value":"content"}]
[task 2022-04-20T04:06:10.409Z] 04:06:06 INFO - 1650427566901 Marionette DEBUG 2 -> [0,27,"Marionette:SetContext",{"value":"chrome"}]
[task 2022-04-20T04:06:10.409Z] 04:06:06 INFO - 1650427566901 Marionette DEBUG 2 <- [1,27,null,{"value":null}]
[task 2022-04-20T04:06:10.409Z] 04:06:06 INFO - 1650427566902 Marionette DEBUG 2 -> [0,28,"WebDriver:GetWindowHandles",{}]
[task 2022-04-20T04:06:10.409Z] 04:06:06 INFO - 1650427566903 Marionette DEBUG 2 <- [1,28,null,["d4d6ff38-dbda-423f-8ce2-9cb1a3fb3024"]]
[task 2022-04-20T04:06:10.409Z] 04:06:06 INFO - 1650427566904 Marionette DEBUG 2 -> [0,29,"Marionette:SetContext",{"value":"content"}]
[task 2022-04-20T04:06:10.409Z] 04:06:06 INFO - 1650427566904 Marionette DEBUG 2 <- [1,29,null,{"value":null}]
[task 2022-04-20T04:06:10.409Z] 04:06:06 INFO - 1650427566905 Marionette DEBUG 2 -> [0,30,"Marionette:GetContext",{}]
[task 2022-04-20T04:06:10.409Z] 04:06:06 INFO - 1650427566905 Marionette DEBUG 2 <- [1,30,null,{"value":"content"}]
[task 2022-04-20T04:06:10.409Z] 04:06:06 INFO - 1650427566906 Marionette DEBUG 2 -> [0,31,"Marionette:SetContext",{"value":"content"}]
[task 2022-04-20T04:06:10.409Z] 04:06:06 INFO - 1650427566906 Marionette DEBUG 2 <- [1,31,null,{"value":null}]
[task 2022-04-20T04:06:10.409Z] 04:06:06 INFO - 1650427566907 Marionette DEBUG 2 -> [0,32,"WebDriver:GetWindowHandles",{}]
[task 2022-04-20T04:06:10.409Z] 04:06:06 INFO - 1650427566907 Marionette DEBUG 2 <- [1,32,null,["988c4f49-952a-4624-a12e-5ecad2aba155"]]
[task 2022-04-20T04:06:10.409Z] 04:06:06 INFO - 1650427566908 Marionette DEBUG 2 -> [0,33,"Marionette:SetContext",{"value":"content"}]
[task 2022-04-20T04:06:10.409Z] 04:06:06 INFO - 1650427566908 Marionette DEBUG 2 <- [1,33,null,{"value":null}]
[task 2022-04-20T04:06:10.409Z] 04:06:10 INFO - TEST-START | telemetry/marionette/tests/client/test_main_tab_scalars.py TestMainTabScalars.test_main_tab_scalars
Description
•