Closed Bug 1753355 Opened 3 years ago Closed 3 years ago

Intermittent telemetry/marionette/tests/client/test_subsession_management.py TestSubsessionManagement.test_subsession_management | AssertionError: Error waiting for ping: Timed out after 60.0 seconds

Categories

(Toolkit :: Telemetry, defect, P5)

Product:
Toolkit
Component:
Telemetry
Type:
defect

Tracking

()

Status:
RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: assertion, intermittent-failure)

Filed by: imoraru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=366551280&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/VDAO_9RZTmWHb7cXJiVi2g/runs/0/artifacts/public/logs/live_backing.log

[task 2022-02-03T02:02:55.168Z] 02:02:55     INFO - TEST-START | telemetry/marionette/tests/client/test_subsession_management.py TestSubsessionManagement.test_subsession_management
[task 2022-02-03T02:02:55.170Z] 02:02:55     INFO - Application command: Z:\task_164385333017747\build\application\firefox\firefox.exe -no-remote -marionette --wait-for-browser -profile Z:\task_164385333017747\build\tmp_ffxroqt.mozrunner
[task 2022-02-03T02:02:55.512Z] 02:02:55     INFO -  1643853775517	Toolkit.Telemetry	TRACE	TelemetryController::observe - profile-after-change notified.
[task 2022-02-03T02:02:55.518Z] 02:02:55     INFO -  1643853775518	Toolkit.Telemetry	TRACE	TelemetryController::setupTelemetry
[task 2022-02-03T02:02:55.519Z] 02:02:55     INFO -  1643853775519	Toolkit.Telemetry	TRACE	TelemetryReportingPolicy::setup
<...>
[task 2022-02-03T02:02:56.628Z] 02:02:56     INFO -  1643853776628	Toolkit.Telemetry	TRACE	TelemetryStorage::removeUninstallPings - success
[task 2022-02-03T02:02:56.629Z] 02:02:56     INFO -  1643853776629	Toolkit.Telemetry	TRACE	TelemetryStorage::savePingToFile - path: C:\ProgramData\Mozilla-1de4eec8-1241-4177-a864-e594e8d1fb38\uninstall_ping_D8430E26AAA2EFE1_81f96aff-7578-4335-8677-67356249072f.json
[task 2022-02-03T02:02:56.850Z] 02:02:56     INFO -  JavaScript error: resource://gre/modules/CaptiveDetect.jsm, line 302: NS_ERROR_FAILURE: No canonical URL set up.
[task 2022-02-03T02:02:57.166Z] 02:02:57     INFO -  1643853777180	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: sessionstore-windows-restored, aData: null
[task 2022-02-03T02:02:57.183Z] 02:02:57     INFO -  1643853777183	Toolkit.Telemetry	TRACE	TelemetrySession::observe - sessionstore-windows-restored notified.
[task 2022-02-03T02:02:57.184Z] 02:02:57     INFO -  1643853777183	Toolkit.Telemetry	TRACE	TelemetrySession::gatherStartup
[task 2022-02-03T02:02:57.184Z] 02:02:57     INFO -  1643853777184	Toolkit.Telemetry	INFO	TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet.
[task 2022-02-03T02:02:57.184Z] 02:02:57     INFO -  1643853777184	Toolkit.Telemetry	TRACE	TelemetryReportingPolicy::_shouldNotify - User already notified or bypassing the policy.
[task 2022-02-03T02:02:57.196Z] 02:02:57     INFO -  1643853777198	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_startWatchingPrefs - [object Map]
[task 2022-02-03T02:02:57.200Z] 02:02:57     INFO -  1643853777200	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.urlbar.quicksuggest.migrationVersion
[task 2022-02-03T02:02:57.200Z] 02:02:57     INFO -  1643853777200	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.urlbar.quicksuggest.scenario
[task 2022-02-03T02:02:57.200Z] 02:02:57     INFO -  1643853777200	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: firefox-suggest-update, aData: null
[task 2022-02-03T02:02:57.207Z] 02:02:57     INFO -  console.warn: SearchSettings: "get: No settings file exists, new profile?" (new NotFoundError("Could not open the file at Z:\\task_164385333017747\\build\\tmp_ffxroqt.mozrunner\\search.json.mozlz4", (void 0)))
[task 2022-02-03T02:02:57.218Z] 02:02:57     INFO -  1643853777218	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.newtabpage.activity-stream.default.sites
[task 2022-02-03T02:02:57.219Z] 02:02:57     INFO -  1643853777218	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: browser.newtabpage.activity-stream.feeds.section.topstories.options
<...>
[task 2022-02-03T02:03:00.012Z] 02:03:00     INFO -  1643853780013	Toolkit.Telemetry	TRACE	TelemetryStorage::_popAndPerformQueuedOperation - Performing queued operation.
[task 2022-02-03T02:03:00.041Z] 02:03:00     INFO -  ###!!! [Parent][PGPUParent] Error: RunMessage(msgname=PGPU::Msg_ShutdownVR) Channel closing: too late to send/recv, messages will be lost
[task 2022-02-03T02:03:00.068Z] 02:03:00     INFO - pingserver pings_handler received 'new-profile' ping
[task 2022-02-03T02:03:00.073Z] 02:03:00     INFO - pingserver pings_handler received 'event' ping
[task 2022-02-03T02:03:00.078Z] 02:03:00     INFO - pingserver pings_handler received 'first-shutdown' ping
[task 2022-02-03T02:03:01.534Z] 02:03:01     INFO - pingserver pings_handler received 'main' ping with reason 'shutdown'
[task 2022-02-03T02:03:01.587Z] 02:03:01     INFO - wait_for_pings running action 'install_addon'.
[task 2022-02-03T02:04:02.055Z] 02:04:02     INFO - TEST-UNEXPECTED-FAIL | telemetry/marionette/tests/client/test_subsession_management.py TestSubsessionManagement.test_subsession_management | AssertionError: Error waiting for ping: Timed out after 60.0 seconds
[task 2022-02-03T02:04:02.055Z] 02:04:02     INFO - Traceback (most recent call last):
[task 2022-02-03T02:04:02.055Z] 02:04:02     INFO -   File "Z:\task_164385333017747\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 202, in run
[task 2022-02-03T02:04:02.055Z] 02:04:02     INFO -     testMethod()
[task 2022-02-03T02:04:02.062Z] 02:04:02     INFO -   File "Z:\task_164385333017747\build\tests\telemetry\marionette\tests\client\test_subsession_management.py", line 69, in test_subsession_management
[task 2022-02-03T02:04:02.062Z] 02:04:02     INFO -     ping2 = self.wait_for_ping(self.install_addon, MAIN_ENVIRONMENT_CHANGE_PING)
[task 2022-02-03T02:04:02.062Z] 02:04:02     INFO -   File "Z:\task_164385333017747\build\venv\lib\site-packages\telemetry_harness\testcase.py", line 169, in wait_for_ping
[task 2022-02-03T02:04:02.062Z] 02:04:02     INFO -     [ping] = self.wait_for_pings(
[task 2022-02-03T02:04:02.062Z] 02:04:02     INFO -   File "Z:\task_164385333017747\build\venv\lib\site-packages\telemetry_harness\testcase.py", line 161, in wait_for_pings
[task 2022-02-03T02:04:02.062Z] 02:04:02     INFO -     self.fail("Error waiting for ping: {}".format(e))
[task 2022-02-03T02:04:02.062Z] 02:04:02     INFO - TEST-INFO took 66818ms
[task 2022-02-03T02:04:02.324Z] 02:04:02     INFO - TEST-START | telemetry/marionette/tests/client/test_fog_background_update_ping.py TestBackgroundUpdatePing.test_background_update_ping

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

Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → INCOMPLETE

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=387233045&repo=mozilla-central

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