Closed Bug 1742803 Opened 4 years ago Closed 4 years ago

Intermittent telemetry/marionette/tests/client/test_event_ping.py TestEventPing.test_event_ping | marionette_driver.errors.ScriptTimeoutException: Timed out after 30000 ms

Categories

(Toolkit :: Telemetry, defect, P5)

Product:
Toolkit
Component:
Telemetry
Type:
defect

Tracking

()

Status:
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=359107019&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/QAtrDfIfSRag6Fn7EnQpGg/runs/0/artifacts/public/logs/live_backing.log

[task 2021-11-24T12:56:55.886Z] 12:56:55     INFO - TEST-START | telemetry/marionette/tests/client/test_event_ping.py TestEventPing.test_event_ping
[task 2021-11-24T12:56:55.886Z] 12:56:55     INFO - Application command: Z:\task_163775699595355\build\application\firefox\firefox.exe -no-remote -marionette --wait-for-browser -profile Z:\task_163775699595355\build\tmp1v8fm207.mozrunner
[task 2021-11-24T12:56:56.461Z] 12:56:56     INFO -  [2021-11-24T12:56:56Z WARN  rkv::backend::impl_safe::environment] `load_ratio()` is irrelevant for this storage backend.
[task 2021-11-24T12:56:56.623Z] 12:56:56     INFO -  1637758616626	Toolkit.Telemetry	TRACE	TelemetryController::observe - profile-after-change notified.
[task 2021-11-24T12:56:56.627Z] 12:56:56     INFO -  1637758616627	Toolkit.Telemetry	TRACE	TelemetryController::setupTelemetry
[task 2021-11-24T12:56:56.629Z] 12:56:56     INFO -  1637758616630	Toolkit.Telemetry	TRACE	TelemetryReportingPolicy::setup
[task 2021-11-24T12:56:56.630Z] 12:56:56     INFO -  1637758616630	Toolkit.Telemetry	CONFIG	TelemetryController::enableTelemetryRecording - canRecordBase:true, canRecordExtended: false
[task 2021-11-24T12:56:56.630Z] 12:56:56     INFO -  1637758616630	Toolkit.Telemetry	TRACE	TelemetrySession::earlyInit
[task 2021-11-24T12:56:56.638Z] 12:56:56     INFO -  1637758616639	Toolkit.Telemetry	INFO	TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet.
[task 2021-11-24T12:56:56.639Z] 12:56:56     INFO -  1637758616640	Toolkit.Telemetry	TRACE	UpdatePing::init - enabled: true
[task 2021-11-24T12:56:56.651Z] 12:56:56     INFO -  1637758616653	Toolkit.Telemetry	TRACE	TelemetryEnvironment::constructor
[task 2021-11-24T12:56:56.682Z] 12:56:56     INFO -  1637758616691	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_getGFXData - Only one display adapter detected.
[task 2021-11-24T12:56:56.696Z] 12:56:56     INFO -  1637758616696	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_updateSearchEngine - ignoring early call
[task 2021-11-24T12:56:56.696Z] 12:56:56     INFO -  1637758616696	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_updateAddons
[task 2021-11-24T12:56:56.699Z] 12:56:56     INFO -  1637758616699	Toolkit.Telemetry	TRACE	TelemetryEnvironment::registerChangeListener for CrashAnnotator
[task 2021-11-24T12:56:56.729Z] 12:56:56     INFO -  1637758616729	Marionette	INFO	Marionette enabled
[task 2021-11-24T12:56:56.865Z] 12:56:56     INFO -  1637758616874	Marionette	TRACE	Received observer notification toplevel-window-ready
[task 2021-11-24T12:56:56.919Z] 12:56:56     INFO -  1637758616925	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_updateAddons: addons differ
[task 2021-11-24T12:56:56.928Z] 12:56:56     INFO -  [Parent 5204, Main Thread] WARNING: NS_ENSURE_TRUE(rootFrame) failed: file /builds/worker/checkouts/gecko/dom/base/nsGlobalWindowOuter.cpp:4239
<...>
[task 2021-11-24T12:57:52.609Z] 12:57:52     INFO -  1637758672609	Marionette	DEBUG	3 <- [1,40,null,{"value":null}]
[task 2021-11-24T12:57:52.687Z] 12:57:52     INFO - TEST-UNEXPECTED-ERROR | telemetry/marionette/tests/client/test_event_ping.py TestEventPing.test_event_ping | marionette_driver.errors.ScriptTimeoutException: Timed out after 30000 ms
[task 2021-11-24T12:57:52.687Z] 12:57:52     INFO - stacktrace:
[task 2021-11-24T12:57:52.695Z] 12:57:52     INFO - 	WebDriverError@chrome://remote/content/shared/webdriver/Errors.jsm:181:5
[task 2021-11-24T12:57:52.695Z] 12:57:52     INFO - 	ScriptTimeoutError@chrome://remote/content/shared/webdriver/Errors.jsm:423:5
[task 2021-11-24T12:57:52.695Z] 12:57:52     INFO - 	evaluate.sandbox/timeoutPromise</scriptTimeoutID<@chrome://remote/content/marionette/evaluate.js:128:16
[task 2021-11-24T12:57:52.695Z] 12:57:52     INFO - 	notify@resource://gre/modules/Timer.jsm:62:17
[task 2021-11-24T12:57:52.695Z] 12:57:52     INFO - Traceback (most recent call last):
[task 2021-11-24T12:57:52.695Z] 12:57:52     INFO -   File "Z:\task_163775699595355\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 202, in run
[task 2021-11-24T12:57:52.695Z] 12:57:52     INFO -     testMethod()
[task 2021-11-24T12:57:52.695Z] 12:57:52     INFO -   File "Z:\task_163775699595355\build\tests\telemetry\marionette\tests\client\test_event_ping.py", line 47, in test_event_ping
[task 2021-11-24T12:57:52.695Z] 12:57:52     INFO -     self.wait_for_search_service_init()
[task 2021-11-24T12:57:52.695Z] 12:57:52     INFO -   File "Z:\task_163775699595355\build\tests\telemetry\marionette\tests\client\test_event_ping.py", line 38, in wait_for_search_service_init
[task 2021-11-24T12:57:52.695Z] 12:57:52     INFO -     self.marionette.execute_async_script(textwrap.dedent(script))
[task 2021-11-24T12:57:52.696Z] 12:57:52     INFO -   File "Z:\task_163775699595355\build\venv\lib\site-packages\marionette_driver\marionette.py", line 1734, in execute_async_script
[task 2021-11-24T12:57:52.696Z] 12:57:52     INFO -     rv = self._send_message("WebDriver:ExecuteAsyncScript", body, key="value")
[task 2021-11-24T12:57:52.696Z] 12:57:52     INFO -   File "Z:\task_163775699595355\build\venv\lib\site-packages\marionette_driver\decorators.py", line 27, in _
[task 2021-11-24T12:57:52.696Z] 12:57:52     INFO -     return func(*args, **kwargs)
[task 2021-11-24T12:57:52.696Z] 12:57:52     INFO -   File "Z:\task_163775699595355\build\venv\lib\site-packages\marionette_driver\marionette.py", line 630, in _send_message
[task 2021-11-24T12:57:52.696Z] 12:57:52     INFO -     self._handle_error(err)
[task 2021-11-24T12:57:52.696Z] 12:57:52     INFO -   File "Z:\task_163775699595355\build\venv\lib\site-packages\marionette_driver\marionette.py", line 652, in _handle_error
[task 2021-11-24T12:57:52.696Z] 12:57:52     INFO -     raise errors.lookup(error)(message, stacktrace=stacktrace)
[task 2021-11-24T12:57:52.696Z] 12:57:52     INFO - TEST-INFO took 56724ms
[task 2021-11-24T12:57:52.696Z] 12:57:52     INFO -  1637758672693	Marionette	DEBUG	3 -> [0,41,"Marionette:GetContext",{}]
[task 2021-11-24T12:57:52.697Z] 12:57:52     INFO -  1637758672693	Marionette	DEBUG	3 <- [1,41,null,{"value":"content"}]
[task 2021-11-24T12:57:52.697Z] 12:57:52     INFO -  1637758672697	Marionette	DEBUG	3 -> [0,42,"Marionette:SetContext",{"value":"chrome"}]
[task 2021-11-24T12:57:52.697Z] 12:57:52     INFO -  1637758672698	Marionette	DEBUG	3 <- [1,42,null,{"value":null}]
[task 2021-11-24T12:57:52.699Z] 12:57:52     INFO -  1637758672699	Marionette	DEBUG	3 -> [0,43,"WebDriver:GetWindowHandles",{}]
[task 2021-11-24T12:57:52.699Z] 12:57:52     INFO -  1637758672700	Marionette	DEBUG	3 <- [1,43,null,["65d64613-2dda-452b-9616-e8e8fc7c0f91"]]
[task 2021-11-24T12:57:52.700Z] 12:57:52     INFO -  1637758672701	Marionette	DEBUG	3 -> [0,44,"Marionette:SetContext",{"value":"content"}]
[task 2021-11-24T12:57:52.701Z] 12:57:52     INFO -  1637758672701	Marionette	DEBUG	3 <- [1,44,null,{"value":null}]
[task 2021-11-24T12:57:52.702Z] 12:57:52     INFO -  1637758672703	Marionette	DEBUG	3 -> [0,45,"Marionette:GetContext",{}]
[task 2021-11-24T12:57:52.702Z] 12:57:52     INFO -  1637758672703	Marionette	DEBUG	3 <- [1,45,null,{"value":"content"}]
[task 2021-11-24T12:57:52.704Z] 12:57:52     INFO -  1637758672704	Marionette	DEBUG	3 -> [0,46,"Marionette:SetContext",{"value":"content"}]
[task 2021-11-24T12:57:52.704Z] 12:57:52     INFO -  1637758672704	Marionette	DEBUG	3 <- [1,46,null,{"value":null}]
[task 2021-11-24T12:57:52.705Z] 12:57:52     INFO -  1637758672705	Marionette	DEBUG	3 -> [0,47,"WebDriver:GetWindowHandles",{}]
[task 2021-11-24T12:57:52.705Z] 12:57:52     INFO -  1637758672706	Marionette	DEBUG	3 <- [1,47,null,["cac45660-fd61-4b17-9912-e7fc9ef39d3b"]]
[task 2021-11-24T12:57:52.707Z] 12:57:52     INFO -  1637758672707	Marionette	DEBUG	3 -> [0,48,"Marionette:SetContext",{"value":"content"}]
[task 2021-11-24T12:57:52.707Z] 12:57:52     INFO -  1637758672707	Marionette	DEBUG	3 <- [1,48,null,{"value":null}]
[task 2021-11-24T12:57:54.780Z] 12:57:54     INFO - TEST-START | telemetry/marionette/tests/client/test_main_tab_scalars.py TestMainTabScalars.test_main_tab_scalars

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.