Closed Bug 1765471 Opened 3 years ago Closed 1 year ago

Intermittent 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

Categories

(Toolkit :: Telemetry, defect, P5)

defect

Tracking

()

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure)

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
Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 3 years ago2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 2 years ago2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 2 years ago2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 2 years ago2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 2 years ago1 year ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 1 year ago1 year ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.