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

Status: RESOLVED INCOMPLETE

(Toolkit :: Telemetry, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: apavel [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=316373124&repo=try
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/E1X3H3SvQZuwP8UmjXG-AA/runs/0/artifacts/public/logs/live_backing.log

---

[task 2020-09-22T12:50:10.014Z] 12:50:10     INFO - TEST-START | telemetry/marionette/tests/client/test_event_ping.py TestEventPing.test_event_ping
[task 2020-09-22T12:50:10.014Z] 12:50:10     INFO - Application command: Z:\task_1600777611\build\application\firefox\firefox.exe -no-remote -marionette --wait-for-browser -profile Z:\task_1600777611\build\tmppnjteu.mozrunner
[task 2020-09-22T12:50:10.422Z] 12:50:10     INFO -  1600779010419	Toolkit.Telemetry	TRACE	TelemetryController::observe - profile-after-change notified.
[task 2020-09-22T12:50:10.422Z] 12:50:10     INFO -  1600779010419	Toolkit.Telemetry	TRACE	TelemetryController::setupTelemetry
[task 2020-09-22T12:50:10.422Z] 12:50:10     INFO -  1600779010421	Toolkit.Telemetry	TRACE	TelemetryReportingPolicy::setup
[task 2020-09-22T12:50:10.422Z] 12:50:10     INFO -  1600779010421	Toolkit.Telemetry	CONFIG	TelemetryController::enableTelemetryRecording - canRecordBase:true, canRecordExtended: true
[task 2020-09-22T12:50:10.422Z] 12:50:10     INFO -  1600779010421	Toolkit.Telemetry	TRACE	TelemetrySession::earlyInit
[task 2020-09-22T12:50:10.427Z] 12:50:10     INFO -  1600779010426	Toolkit.Telemetry	INFO	TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet.
[task 2020-09-22T12:50:10.429Z] 12:50:10     INFO -  1600779010427	Toolkit.Telemetry	TRACE	UpdatePing::init - enabled: true
[task 2020-09-22T12:50:10.434Z] 12:50:10     INFO -  1600779010431	Toolkit.Telemetry	TRACE	TelemetryEnvironment::constructor
[task 2020-09-22T12:50:10.439Z] 12:50:10     INFO -  1600779010436	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_getGFXData - Only one display adapter detected.
[task 2020-09-22T12:50:10.439Z] 12:50:10     INFO -  1600779010438	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_updateSearchEngine - ignoring early call
[task 2020-09-22T12:50:10.441Z] 12:50:10     INFO -  1600779010438	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_updateAddons
[task 2020-09-22T12:50:10.443Z] 12:50:10     INFO -  1600779010440	Toolkit.Telemetry	TRACE	TelemetryEnvironment::registerChangeListener for CrashAnnotator
[task 2020-09-22T12:50:10.453Z] 12:50:10     INFO -  1600779010450	Marionette	TRACE	Marionette enabled
[task 2020-09-22T12:50:10.498Z] 12:50:10     INFO -  1600779010494	Marionette	TRACE	Received observer notification toplevel-window-ready
[task 2020-09-22T12:50:10.517Z] 12:50:10     INFO -  1600779010508	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_updateAddons: addons differ
[task 2020-09-22T12:50:10.716Z] 12:50:10     INFO -  1600779010706	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: auto-update-config-change, aData: false
[task 2020-09-22T12:50:10.779Z] 12:50:10     INFO -  1600779010775	Toolkit.Telemetry	TRACE	TelemetrySession::observe - xul-window-visible notified.
[task 2020-09-22T12:50:10.830Z] 12:50:10     INFO -  1600779010826	Toolkit.Telemetry	TRACE	TelemetryController::observe - app-startup notified.
[task 2020-09-22T12:50:10.830Z] 12:50:10     INFO -  1600779010827	Toolkit.Telemetry	CONFIG	TelemetryController::enableTelemetryRecording - canRecordBase:true, canRecordExtended: true
[task 2020-09-22T12:50:10.951Z] 12:50:10     INFO -  1600779010937	Toolkit.Telemetry	TRACE	TelemetryController::observe - app-startup notified.
[task 2020-09-22T12:50:10.951Z] 12:50:10     INFO -  1600779010938	Toolkit.Telemetry	CONFIG	TelemetryController::enableTelemetryRecording - canRecordBase:true, canRecordExtended: true
[task 2020-09-22T12:50:10.990Z] 12:50:10     INFO -  1600779010981	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: compositor:created, aData: null
[task 2020-09-22T12:50:11.013Z] 12:50:11     INFO -  JavaScript error: , line 0: UnknownError: The operation failed for reasons unrelated to the database itself and not covered by any other error code.
[task 2020-09-22T12:50:11.013Z] 12:50:11     INFO -  JavaScript error: , line 0: uncaught exception: null

[task 2020-09-22T12:50:12.628Z] 12:50:12     INFO -  JavaScript error: , line 0: uncaught exception: 2147549183
[task 2020-09-22T12:50:13.600Z] 12:50:13     INFO -  1600779013588	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.newtabpage.storageVersion
[task 2020-09-22T12:50:16.075Z] 12:50:16     INFO -  1600779016073	Toolkit.Telemetry	TRACE	TelemetrySession::observe - user-interaction-active notified.
[task 2020-09-22T12:50:21.082Z] 12:50:21     INFO -  1600779021075	Toolkit.Telemetry	TRACE	TelemetrySession::observe - user-interaction-inactive notified.
[task 2020-09-22T12:50:31.682Z] 12:50:31     INFO -  1600779031678	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: media.gmp-manager.buildID
[task 2020-09-22T12:50:31.682Z] 12:50:31     INFO -  1600779031678	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: media.gmp-manager.lastCheck
[task 2020-09-22T12:50:40.455Z] 12:50:40     INFO -  1600779040450	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: app.update.lastUpdateTime.services-settings-poll-changes
[task 2020-09-22T12:50:40.455Z] 12:50:40     INFO -  1600779040450	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: app.update.lastUpdateTime.addon-background-update-timer
[task 2020-09-22T12:50:40.455Z] 12:50:40     INFO -  1600779040451	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: app.update.lastUpdateTime.search-engine-update-timer
[task 2020-09-22T12:50:40.455Z] 12:50:40     INFO -  1600779040451	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: app.update.lastUpdateTime.background-update-timer
[task 2020-09-22T12:50:40.455Z] 12:50:40     INFO -  1600779040451	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: app.update.lastUpdateTime.browser-cleanup-thumbnails
[task 2020-09-22T12:50:41.774Z] 12:50:41     INFO -  1600779041765	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: toolkit.startup.last_success
[task 2020-09-22T12:50:42.630Z] 12:50:42     INFO -  1600779042627	Marionette	DEBUG	3 <- [1,19,{"error":"script timeout","message":"Timed out after 30000 ms","stacktrace":"WebDriverError@chrome://marionette/content ... ise</scriptTimeoutID<@chrome://marionette/content/evaluate.js:108:16\nnotify@resource://gre/modules/Timer.jsm:62:17\n"},null]
[task 2020-09-22T12:50:42.630Z] 12:50:42     INFO -  1600779042629	Marionette	DEBUG	3 -> [0,20,"Marionette:SetContext",{"value":"content"}]
[task 2020-09-22T12:50:42.630Z] 12:50:42     INFO -  1600779042629	Marionette	DEBUG	3 <- [1,20,null,{"value":null}]
[task 2020-09-22T12:50:42.635Z] 12:50:42     INFO -  1600779042631	Marionette	DEBUG	3 -> [0,21,"Marionette:GetContext",{}]
[task 2020-09-22T12:50:42.635Z] 12:50:42     INFO -  1600779042631	Marionette	DEBUG	3 <- [1,21,null,{"value":"content"}]
[task 2020-09-22T12:50:42.635Z] 12:50:42     INFO -  1600779042632	Marionette	DEBUG	3 -> [0,22,"Marionette:SetContext",{"value":"chrome"}]
[task 2020-09-22T12:50:42.635Z] 12:50:42     INFO -  1600779042632	Marionette	DEBUG	3 <- [1,22,null,{"value":null}]
[task 2020-09-22T12:50:42.635Z] 12:50:42     INFO -  1600779042633	Marionette	DEBUG	3 -> [0,23,"WebDriver:TakeScreenshot",{"full":true,"hash":false,"id":null,"scroll":true}]
[task 2020-09-22T12:50:42.704Z] 12:50:42     INFO -  1600779042700	Marionette	DEBUG	3 <- [1,23,null,{"value":"iVBORw0KGgoAAAANSUhEUgAABAAAAAMHCAYAAACnvyW1AAAgAElEQVR4nOzdX6wdx30gaL7MIrNz+SzD8tv1ix2QIikqcmTNiNa1xHhH ... xg17mETTKUvl9Vy4F62Cc3cyD9tGCc4Mu9tyO9DsQzArra9tTrUlsdAXgbEgAAAABQAAkAAAAAKIAEAAAAABTgJRIA/w8IcBVbrSx9dgAAAABJRU5ErkJggg=="}]
[task 2020-09-22T12:50:42.704Z] 12:50:42     INFO -  1600779042702	Marionette	DEBUG	3 -> [0,24,"Marionette:SetContext",{"value":"content"}]
[task 2020-09-22T12:50:42.704Z] 12:50:42     INFO -  1600779042702	Marionette	DEBUG	3 <- [1,24,null,{"value":null}]
[task 2020-09-22T12:50:42.706Z] 12:50:42     INFO -  1600779042704	Marionette	DEBUG	3 -> [0,25,"Marionette:GetContext",{}]
[task 2020-09-22T12:50:42.706Z] 12:50:42     INFO -  1600779042704	Marionette	DEBUG	3 <- [1,25,null,{"value":"content"}]
[task 2020-09-22T12:50:42.706Z] 12:50:42     INFO -  1600779042705	Marionette	DEBUG	3 -> [0,26,"Marionette:SetContext",{"value":"content"}]
[task 2020-09-22T12:50:42.706Z] 12:50:42     INFO -  1600779042705	Marionette	DEBUG	3 <- [1,26,null,{"value":null}]
[task 2020-09-22T12:50:42.708Z] 12:50:42     INFO -  1600779042706	Marionette	DEBUG	3 -> [0,27,"WebDriver:GetPageSource",{}]
[task 2020-09-22T12:50:42.710Z] 12:50:42     INFO -  1600779042707	Marionette	DEBUG	3 <- [1,27,null,{"value":"<html xmlns=\"http://www.w3.org/1999/xhtml\" dir=\"ltr\" lang=\"en-US\"><head>\n  <meta charset=\"utf-8\ ... bout:webrtc\">about:webrtc</a></li><li><a href=\"about:welcome\">about:welcome</a></li></ul>\n  </div>\n\n\n</body></html>"}]
[task 2020-09-22T12:50:42.710Z] 12:50:42     INFO -  1600779042708	Marionette	DEBUG	3 -> [0,28,"Marionette:SetContext",{"value":"content"}]
[task 2020-09-22T12:50:42.710Z] 12:50:42     INFO -  1600779042709	Marionette	DEBUG	3 <- [1,28,null,{"value":null}]
[task 2020-09-22T12:50:42.729Z] 12:50:42     INFO - TEST-UNEXPECTED-ERROR | telemetry/marionette/tests/client/test_event_ping.py TestEventPing.test_event_ping | ScriptTimeoutException: Timed out after 30000 ms
[task 2020-09-22T12:50:42.729Z] 12:50:42     INFO - stacktrace:
[task 2020-09-22T12:50:42.729Z] 12:50:42     INFO - 	WebDriverError@chrome://marionette/content/error.js:181:5
[task 2020-09-22T12:50:42.729Z] 12:50:42     INFO - 	ScriptTimeoutError@chrome://marionette/content/error.js:423:5
[task 2020-09-22T12:50:42.729Z] 12:50:42     INFO - 	evaluate.sandbox/timeoutPromise</scriptTimeoutID<@chrome://marionette/content/evaluate.js:108:16
[task 2020-09-22T12:50:42.729Z] 12:50:42     INFO - 	notify@resource://gre/modules/Timer.jsm:62:17
[task 2020-09-22T12:50:42.729Z] 12:50:42     INFO - Traceback (most recent call last):
[task 2020-09-22T12:50:42.729Z] 12:50:42     INFO -   File "Z:\task_1600777611\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 196, in run
[task 2020-09-22T12:50:42.729Z] 12:50:42     INFO -     testMethod()
[task 2020-09-22T12:50:42.729Z] 12:50:42     INFO -   File "Z:\task_1600777611\build\tests\telemetry\marionette\tests\client\test_event_ping.py", line 47, in test_event_ping
[task 2020-09-22T12:50:42.729Z] 12:50:42     INFO -     self.wait_for_search_service_init()
[task 2020-09-22T12:50:42.729Z] 12:50:42     INFO -   File "Z:\task_1600777611\build\tests\telemetry\marionette\tests\client\test_event_ping.py", line 38, in wait_for_search_service_init
[task 2020-09-22T12:50:42.729Z] 12:50:42     INFO -     self.marionette.execute_async_script(textwrap.dedent(script))
[task 2020-09-22T12:50:42.730Z] 12:50:42     INFO -   File "Z:\task_1600777611\build\venv\lib\site-packages\marionette_driver\marionette.py", line 1652, in execute_async_script
[task 2020-09-22T12:50:42.730Z] 12:50:42     INFO -     rv = self._send_message("WebDriver:ExecuteAsyncScript", body, key="value")
[task 2020-09-22T12:50:42.730Z] 12:50:42     INFO -   File "Z:\task_1600777611\build\venv\lib\site-packages\marionette_driver\decorators.py", line 26, in _
[task 2020-09-22T12:50:42.730Z] 12:50:42     INFO -     return func(*args, **kwargs)
[task 2020-09-22T12:50:42.730Z] 12:50:42     INFO -   File "Z:\task_1600777611\build\venv\lib\site-packages\marionette_driver\marionette.py", line 602, in _send_message
[task 2020-09-22T12:50:42.730Z] 12:50:42     INFO -     self._handle_error(err)
[task 2020-09-22T12:50:42.730Z] 12:50:42     INFO -   File "Z:\task_1600777611\build\venv\lib\site-packages\marionette_driver\marionette.py", line 622, in _handle_error
[task 2020-09-22T12:50:42.730Z] 12:50:42     INFO -     raise errors.lookup(error)(message, stacktrace=stacktrace)
[task 2020-09-22T12:50:42.730Z] 12:50:42     INFO - TEST-INFO took 32698ms
[task 2020-09-22T12:50:42.730Z] 12:50:42     INFO -  1600779042723	Marionette	DEBUG	3 -> [0,29,"WebDriver:GetChromeWindowHandles",{}]
[task 2020-09-22T12:50:42.730Z] 12:50:42     INFO -  1600779042723	Marionette	DEBUG	3 <- [1,29,null,["8"]]
[task 2020-09-22T12:50:42.730Z] 12:50:42     INFO -  1600779042724	Marionette	DEBUG	3 -> [0,30,"WebDriver:GetWindowHandles",{}]
[task 2020-09-22T12:50:42.730Z] 12:50:42     INFO -  1600779042725	Marionette	DEBUG	3 <- [1,30,null,["29"]]```

Comment 1

[Intermittent Failures Robot]

2 failures in 4019 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 2

Platform breakdown:

• windows10-64: 1
• windows10-64-devedition: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1666543&startday=2020-09-21&endday=2020-09-27&tree=all

Comment 2

[Intermittent Failures Robot]

3 failures in 4195 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-beta: 3

Platform breakdown:

• linux1804-64-asan: 1
• linux1804-64-shippable: 1
• linux1804-64-devedition: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1666543&startday=2020-09-28&endday=2020-10-04&tree=all

Comment 3

[BugBot [:suhaib / :marco/ :calixte]]

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