Closed Bug 1899158 Opened 1 year ago Closed 1 year ago

Intermittent TV toolkit/components/telemetry/tests/unit/test_TelemetryController.js | single tracking bug

Categories

(Toolkit :: Telemetry, defect, P5)

Product:
Toolkit
Component:
Telemetry
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
128 Branch
Tracking Flags:
Tracking Status
firefox-esr115 --- unaffected
firefox126 --- unaffected
firefox127 --- unaffected
firefox128 --- fixed

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Regression)

Details

(Keywords: intermittent-failure, regression, test-verify-fail)

Filed by: ctuns [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=459820607&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/WZqmOPCLSPK6X2VCFA2Oww/runs/0/artifacts/public/logs/live_backing.log
Reftest URL: https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/WZqmOPCLSPK6X2VCFA2Oww/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

[task 2024-05-27T14:22:09.739Z] 14:22:09     INFO -  SUITE-START | Running 1 tests
[task 2024-05-27T14:22:09.740Z] 14:22:09     INFO -  TEST-START | toolkit/components/telemetry/tests/unit/test_TelemetryController.js
[task 2024-05-27T14:22:11.867Z] 14:22:11  WARNING -  TEST-UNEXPECTED-FAIL | toolkit/components/telemetry/tests/unit/test_TelemetryController.js | xpcshell return code: 0
[task 2024-05-27T14:22:11.868Z] 14:22:11     INFO -  TEST-INFO took 2128ms
[task 2024-05-27T14:22:11.868Z] 14:22:11     INFO -  >>>>>>>
[task 2024-05-27T14:22:11.868Z] 14:22:11     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2024-05-27T14:22:11.868Z] 14:22:11     INFO -  (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2024-05-27T14:22:11.869Z] 14:22:11     INFO -  (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2024-05-27T14:22:11.869Z] 14:22:11     INFO -  running event loop
[task 2024-05-27T14:22:11.869Z] 14:22:11     INFO -  toolkit/components/telemetry/tests/unit/test_TelemetryController.js | Starting test_setup
[task 2024-05-27T14:22:11.869Z] 14:22:11     INFO -  (xpcshell/head.js) | test test_setup pending (2)
[task 2024-05-27T14:22:11.869Z] 14:22:11     INFO -  (xpcshell/head.js) | test run_next_test 0 finished (2)
[task 2024-05-27T14:22:11.869Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729938	addons.manager	DEBUG	Application has been upgraded"
[task 2024-05-27T14:22:11.870Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729940	addons.manager	DEBUG	Loaded provider scope for resource://gre/modules/addons/GMPProvider.sys.mjs"
[task 2024-05-27T14:22:11.870Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729942	addons.manager	DEBUG	Loaded provider scope for resource://gre/modules/addons/SitePermsAddonProvider.sys.mjs"
[task 2024-05-27T14:22:11.870Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729942	addons.manager	DEBUG	Starting provider: XPIProvider"
[task 2024-05-27T14:22:11.871Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729942	addons.xpi	DEBUG	startup"
[task 2024-05-27T14:22:11.871Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729942	addons.xpi	INFO	SystemAddonLocation directory is missing"
[task 2024-05-27T14:22:11.871Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729949	addons.xpi	INFO	Removing all system add-on upgrades."
[task 2024-05-27T14:22:11.871Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729949	addons.xpi	DEBUG	checkForChanges"
[task 2024-05-27T14:22:11.872Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729949	addons.xpi	DEBUG	Loaded add-on state: ${}"
[task 2024-05-27T14:22:11.872Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729950	addons.xpi	DEBUG	New add-on tel-system-xpi@tests.mozilla.org in app-system-defaults"
[task 2024-05-27T14:22:11.872Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729950	addons.xpi	WARN	Can't get modified time of /var/folders/wx/9pd2d09d01b4scy1m7mwwjf8000014/T/xpc-profile-jr24ehj5/sysfeatures/app0/tel-system-xpi@tests.mozilla.org.xpi"
[task 2024-05-27T14:22:11.872Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729950	addons.xpi	DEBUG	scanForChanges changed: true, state: {}"
[task 2024-05-27T14:22:11.873Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729956	addons.xpi-utils	DEBUG	Synchronously loading the add-ons database"
[task 2024-05-27T14:22:11.873Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729956	addons.xpi-utils	DEBUG	Starting async load of XPI database /var/folders/wx/9pd2d09d01b4scy1m7mwwjf8000014/T/xpc-profile-jr24ehj5/extensions.json"
[task 2024-05-27T14:22:11.873Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729958	addons.xpi-utils	DEBUG	New add-on tel-system-xpi@tests.mozilla.org installed in app-system-defaults"
[task 2024-05-27T14:22:11.874Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729959	addons.xpi-utils	WARN	addMetadata: Add-on tel-system-xpi@tests.mozilla.org is invalid: [Exception... "Component returned failure code: 0x80520012 (NS_ERROR_FILE_NOT_FOUND) [nsIFile.isFile]"  nsresult: "0x80520012 (NS_ERROR_FILE_NOT_FOUND)"  location: "JS frame :: resource://gre/modules/addons/XPIInstall.sys.mjs :: get :: line 207"  data: no] Stack trace: get()@resource://gre/modules/addons/XPIInstall.sys.mjs:207
[task 2024-05-27T14:22:11.874Z] 14:22:11     INFO -  syncLoadManifest()@resource://gre/modules/addons/XPIInstall.sys.mjs:797
[task 2024-05-27T14:22:11.874Z] 14:22:11     INFO -  addMetadata()@resource://gre/modules/addons/XPIDatabase.sys.mjs:3199
[task 2024-05-27T14:22:11.874Z] 14:22:11     INFO -  processFileChanges()@resource://gre/modules/addons/XPIDatabase.sys.mjs:3684
[task 2024-05-27T14:22:11.875Z] 14:22:11     INFO -  checkForChanges()@resource://gre/modules/addons/XPIProvider.sys.mjs:3122
[task 2024-05-27T14:22:11.875Z] 14:22:11     INFO -  startup()@resource://gre/modules/addons/XPIProvider.sys.mjs:2526
[task 2024-05-27T14:22:11.875Z] 14:22:11     INFO -  callProvider()@resource://gre/modules/AddonManager.sys.mjs:225
[task 2024-05-27T14:22:11.875Z] 14:22:11     INFO -  _startProvider()@resource://gre/modules/AddonManager.sys.mjs:534
[task 2024-05-27T14:22:11.875Z] 14:22:11     INFO -  startup()@resource://gre/modules/AddonManager.sys.mjs:747
[task 2024-05-27T14:22:11.876Z] 14:22:11     INFO -  startup()@resource://gre/modules/AddonManager.sys.mjs:3640
[task 2024-05-27T14:22:11.876Z] 14:22:11     INFO -  observe()@resource://gre/modules/amManager.sys.mjs:73
[task 2024-05-27T14:22:11.876Z] 14:22:11     INFO -  promiseStartupManager()@resource://testing-common/AddonTestUtils.sys.mjs:853
[task 2024-05-27T14:22:11.876Z] 14:22:11     INFO -  loadAddonManager()@/opt/worker/tasks/task_171681649062365/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/head.js:295
[task 2024-05-27T14:22:11.876Z] 14:22:11     INFO -  _do_main()@/opt/worker/tasks/task_171681649062365/build/tests/xpcshell/head.js:245
[task 2024-05-27T14:22:11.877Z] 14:22:11     INFO -  _execute_test()@/opt/worker/tasks/task_171681649062365/build/tests/xpcshell/head.js:596
[task 2024-05-27T14:22:11.877Z] 14:22:11     INFO -  -e:1"
[task 2024-05-27T14:22:11.877Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729960	addons.xpi-utils	WARN	Could not uninstall invalid item from locked install location"
[task 2024-05-27T14:22:11.877Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729961	addons.xpi-utils	DEBUG	Updating add-on states"
[task 2024-05-27T14:22:11.877Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729963	addons.manager	DEBUG	Registering shutdown blocker for XPIProvider"
[task 2024-05-27T14:22:11.878Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729963	addons.manager	DEBUG	Provider finished startup: XPIProvider"
[task 2024-05-27T14:22:11.878Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729963	addons.manager	DEBUG	Completed startup sequence"
[task 2024-05-27T14:22:11.878Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729973	Toolkit.Telemetry	TRACE	TelemetryEnvironment::constructor"
[task 2024-05-27T14:22:11.878Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729979	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_getGFXData - Only one display adapter detected."
[task 2024-05-27T14:22:11.878Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729982	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_updateSearchEngine - ignoring early call"
[task 2024-05-27T14:22:11.878Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729982	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_updateAddons"
[task 2024-05-27T14:22:11.879Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729983	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_updateAddons: addons differ"
[task 2024-05-27T14:22:11.879Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729986	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_startWatchingPrefs - [object Map]"
[task 2024-05-27T14:22:11.879Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729986	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_stopWatchingPrefs"
[task 2024-05-27T14:22:11.879Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729987	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_updateSearchEngine - ignoring early call"
[task 2024-05-27T14:22:11.880Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729987	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_startWatchingPrefs - [object Map]"
[task 2024-05-27T14:22:11.880Z] 14:22:11     INFO -  (xpcshell/head.js) | test run_next_test 1 pending (2)
[task 2024-05-27T14:22:11.880Z] 14:22:11     INFO -  (xpcshell/head.js) | test test_setup finished (2)
[task 2024-05-27T14:22:11.880Z] 14:22:11     INFO -  toolkit/components/telemetry/tests/unit/test_TelemetryController.js | Starting asyncSetup
[task 2024-05-27T14:22:11.880Z] 14:22:11     INFO -  (xpcshell/head.js) | test asyncSetup pending (2)
[task 2024-05-27T14:22:11.881Z] 14:22:11     INFO -  (xpcshell/head.js) | test run_next_test 1 finished (2)
[task 2024-05-27T14:22:11.881Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729988	Toolkit.Telemetry	TRACE	TelemetryController::setupTelemetry"
[task 2024-05-27T14:22:11.881Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729988	Toolkit.Telemetry	TRACE	TelemetryController::registerJsProbes - registering builtin JS probes"
[task 2024-05-27T14:22:11.881Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729988	Toolkit.Telemetry	TRACE	TelemetryController::registerScalarProbes - registering scalar builtin JS probes"
[task 2024-05-27T14:22:11.881Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729988	Toolkit.Telemetry	TRACE	TelemetryController::loadProbeDefinitions - no builtin JS probe file ScalarArtifactDefinitions.json"
[task 2024-05-27T14:22:11.882Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729989	Toolkit.Telemetry	TRACE	TelemetryReportingPolicy::setup"
[task 2024-05-27T14:22:11.882Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729989	Toolkit.Telemetry	CONFIG	TelemetryController::enableTelemetryRecording - canRecordBase:true, canRecordExtended: true"
[task 2024-05-27T14:22:11.882Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729989	Toolkit.Telemetry	TRACE	TelemetrySession::earlyInit"
[task 2024-05-27T14:22:11.882Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729989	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: toolkit.telemetry.previousBuildID"
[task 2024-05-27T14:22:11.883Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729989	Toolkit.Telemetry	INFO	TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet."
[task 2024-05-27T14:22:11.883Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729990	Toolkit.Telemetry	TRACE	UpdatePing::init - enabled: true"
[task 2024-05-27T14:22:11.883Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729990	Toolkit.Telemetry	TRACE	TelemetryController::registerEventProbes - registering builtin JS Event probes"
[task 2024-05-27T14:22:11.883Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729990	Toolkit.Telemetry	TRACE	TelemetryController::loadProbeDefinitions - no builtin JS probe file EventArtifactDefinitions.json"
[task 2024-05-27T14:22:11.883Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729994	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_onEnvironmentChange for system-info"
[task 2024-05-27T14:22:11.884Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729994	Toolkit.Telemetry	TRACE	ClientID::_doLoadClientID"
[task 2024-05-27T14:22:11.884Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729996	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: toolkit.telemetry.cachedClientID"
[task 2024-05-27T14:22:11.884Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729996	Toolkit.Telemetry	TRACE	ClientID::_saveClientID"
[task 2024-05-27T14:22:11.884Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729996	Toolkit.Telemetry	TRACE	ClientID::_doLoadClientID: New client ID loaded and persisted."
[task 2024-05-27T14:22:11.885Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729996	Toolkit.Telemetry	TRACE	TelemetrySend::setup"
[task 2024-05-27T14:22:11.885Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729997	Toolkit.Telemetry	INFO	TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet."
[task 2024-05-27T14:22:11.885Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729997	Toolkit.Telemetry	TRACE	TelemetryStorage::_scanPendingPings"
[task 2024-05-27T14:22:11.885Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729997	Toolkit.Telemetry	TRACE	TelemetryStorage::_migrateAppDataPings"
[task 2024-05-27T14:22:11.885Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729997	Toolkit.Telemetry	TRACE	TelemetryStorage::_iterateAppDataPings"
[task 2024-05-27T14:22:11.886Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729997	Toolkit.Telemetry	TRACE	TelemetryStorage::_iterateAppDataPings - userApplicationDataDir is not defined. Is this a test?"
[task 2024-05-27T14:22:11.886Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729997	Toolkit.Telemetry	INFO	TelemetrySend::_checkPendingPings - pending ping count: 0"
[task 2024-05-27T14:22:11.886Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729997	Toolkit.Telemetry	TRACE	TelemetrySend::_checkPendingPings - no pending pings"
[task 2024-05-27T14:22:11.887Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729997	Toolkit.Telemetry	TRACE	TelemetryStorage::_enforcePendingPingsQuota"
[task 2024-05-27T14:22:11.887Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729997	Toolkit.Telemetry	TRACE	TelemetrySend::Scheduler::triggerSendingPings - active send task: false, immediately: true"
[task 2024-05-27T14:22:11.887Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729997	Toolkit.Telemetry	TRACE	TelemetrySend::Scheduler::_doSendTask iteration"
[task 2024-05-27T14:22:11.887Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729997	Toolkit.Telemetry	TRACE	TelemetrySend::Scheduler::_doSendTask - pending: 0, current: 0"
[task 2024-05-27T14:22:11.888Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729997	Toolkit.Telemetry	TRACE	TelemetrySend::Scheduler::_doSendTask - can send - pending: 0, current: 0"
[task 2024-05-27T14:22:11.888Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729997	Toolkit.Telemetry	TRACE	TelemetrySend::Scheduler::_doSendTask - no pending pings, bailing out"
[task 2024-05-27T14:22:11.888Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729997	Toolkit.Telemetry	TRACE	TelemetrySession::delayedInit"
[task 2024-05-27T14:22:11.888Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729997	Toolkit.Telemetry	TRACE	TelemetryStorage::_popAndPerformQueuedOperation - Performing queued operation."
[task 2024-05-27T14:22:11.889Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729998	Toolkit.Telemetry	INFO	TelemetryStorage::_loadSessionData - can not load session data file: NotFoundError: Could not open `/var/folders/wx/9pd2d09d01b4scy1m7mwwjf8000014/T/xpc-profile-jr24ehj5/datareporting/session-state.json': file does not exist (NS_ERROR_FILE_NOT_FOUND) Stack trace: _do_main()@/opt/worker/tasks/task_171681649062365/build/tests/xpcshell/head.js:245
[task 2024-05-27T14:22:11.889Z] 14:22:11     INFO -  _execute_test()@/opt/worker/tasks/task_171681649062365/build/tests/xpcshell/head.js:596
[task 2024-05-27T14:22:11.889Z] 14:22:11     INFO -  -e:1"
[task 2024-05-27T14:22:11.889Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729998	Toolkit.Telemetry	TRACE	TelemetryStorage::_popAndPerformQueuedOperation - Performing queued operation."
[task 2024-05-27T14:22:11.890Z] 14:22:11     INFO -  (xpcshell/head.js) | test run_next_test 2 pending (2)
[task 2024-05-27T14:22:11.890Z] 14:22:11     INFO -  (xpcshell/head.js) | test asyncSetup finished (2)
[task 2024-05-27T14:22:11.890Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729999	addons.xpi-utils	DEBUG	XPI Database saved, setting schema version preference to 36"
[task 2024-05-27T14:22:11.890Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729999	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: extensions.databaseSchema"
[task 2024-05-27T14:22:11.891Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729999	Toolkit.Telemetry	TRACE	TelemetryStorage::loadPingfile - unreadable ping /var/folders/wx/9pd2d09d01b4scy1m7mwwjf8000014/T/xpc-profile-jr24ehj5/datareporting/aborted-session-ping: NotFoundError: Could not open `/var/folders/wx/9pd2d09d01b4scy1m7mwwjf8000014/T/xpc-profile-jr24ehj5/datareporting/aborted-session-ping': file does not exist (NS_ERROR_FILE_NOT_FOUND) Stack trace: _do_main()@/opt/worker/tasks/task_171681649062365/build/tests/xpcshell/head.js:245
[task 2024-05-27T14:22:11.891Z] 14:22:11     INFO -  _execute_test()@/opt/worker/tasks/task_171681649062365/build/tests/xpcshell/head.js:596
[task 2024-05-27T14:22:11.891Z] 14:22:11     INFO -  -e:1"
[task 2024-05-27T14:22:11.892Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729999	Toolkit.Telemetry	TRACE	TelemetryStorage::loadAbortedSessionPing - no such file"
[task 2024-05-27T14:22:11.892Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729999	Toolkit.Telemetry	TRACE	TelemetryController::checkAbortedSessionPing - found aborted-session ping: false"
[task 2024-05-27T14:22:11.892Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729999	Toolkit.Telemetry	TRACE	TelemetryEnvironment::registerChangeListener for TelemetrySession::onEnvironmentChange"
[task 2024-05-27T14:22:11.892Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729999	Toolkit.Telemetry	TRACE	TelemetryScheduler::init"
[task 2024-05-27T14:22:11.893Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819729999	Toolkit.Telemetry	TRACE	TelemetryScheduler::_rescheduleTimeout - isUserIdle: false"
[task 2024-05-27T14:22:11.893Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819730000	Toolkit.Telemetry	TRACE	TelemetryScheduler::_rescheduleTimeout - scheduling next tick for Mon May 27 2024 14:27:09 GMT+0000 (Greenwich Mean Time)"
[task 2024-05-27T14:22:11.893Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819730000	Toolkit.Telemetry	TRACE	TelemetryStorage::cleanArchiveTask"
[task 2024-05-27T14:22:11.893Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819730000	Toolkit.Telemetry	TRACE	TelemetryStorage::removeFHRDatabase"
[task 2024-05-27T14:22:11.894Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819730001	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: app.update.lastUpdateTime.telemetry_modules_ping"
[task 2024-05-27T14:22:11.894Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819730002	Toolkit.Telemetry	TRACE	TelemetryEventPing::::Starting up."
[task 2024-05-27T14:22:11.894Z] 14:22:11     INFO -  toolkit/components/telemetry/tests/unit/test_TelemetryController.js | Starting test_overwritePing
[task 2024-05-27T14:22:11.894Z] 14:22:11     INFO -  (xpcshell/head.js) | test test_overwritePing pending (2)
[task 2024-05-27T14:22:11.894Z] 14:22:11     INFO -  (xpcshell/head.js) | test run_next_test 2 finished (2)
[task 2024-05-27T14:22:11.895Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819730003	Toolkit.Telemetry	TRACE	TelemetryStorage::savePingToFile - path: /var/folders/wx/9pd2d09d01b4scy1m7mwwjf8000014/T/xpc-profile-jr24ehj5/saved-telemetry-pings/foo"
[task 2024-05-27T14:22:11.895Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819730004	Toolkit.Telemetry	TRACE	TelemetryStorage::savePingToFile - path: /var/folders/wx/9pd2d09d01b4scy1m7mwwjf8000014/T/xpc-profile-jr24ehj5/saved-telemetry-pings/foo"
[task 2024-05-27T14:22:11.895Z] 14:22:11     INFO -  (xpcshell/head.js) | test run_next_test 3 pending (2)
[task 2024-05-27T14:22:11.895Z] 14:22:11     INFO -  (xpcshell/head.js) | test test_overwritePing finished (2)
[task 2024-05-27T14:22:11.896Z] 14:22:11     INFO -  toolkit/components/telemetry/tests/unit/test_TelemetryController.js | Starting test_simplePing
[task 2024-05-27T14:22:11.896Z] 14:22:11     INFO -  (xpcshell/head.js) | test test_simplePing pending (2)
[task 2024-05-27T14:22:11.896Z] 14:22:11     INFO -  (xpcshell/head.js) | test run_next_test 3 finished (2)
[task 2024-05-27T14:22:11.896Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819730010	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: toolkit.telemetry.server"
[task 2024-05-27T14:22:11.896Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819730010	Toolkit.Telemetry	TRACE	TelemetrySend::setServer: http://localhost:49424"
[task 2024-05-27T14:22:11.897Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819730010	Toolkit.Telemetry	TRACE	TelemetryController::submitExternalPing - type: test-ping-type, aOptions: {"addClientId":false,"addEnvironment":false,"usePingSender":false}"
[task 2024-05-27T14:22:11.897Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819730010	Toolkit.Telemetry	TRACE	TelemetryController::assemblePing - Type test-ping-type, aOptions {"addClientId":false,"addEnvironment":false,"usePingSender":false}"
[task 2024-05-27T14:22:11.897Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819730011	Toolkit.Telemetry	TRACE	TelemetryController::submitExternalPing - ping assembled, id: 8c48d273-fa38-49f6-bdb7-78a938c2bdf7"
[task 2024-05-27T14:22:11.898Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819730011	Toolkit.Telemetry	TRACE	TelemetrySend::submitPing - ping id: 8c48d273-fa38-49f6-bdb7-78a938c2bdf7, options: {"usePingSender":false}"
[task 2024-05-27T14:22:11.898Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819730011	Toolkit.Telemetry	INFO	TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet."
[task 2024-05-27T14:22:11.898Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819730011	Toolkit.Telemetry	TRACE	TelemetrySend::submitPing - can send pings, trying to send now"
[task 2024-05-27T14:22:11.899Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819730011	Toolkit.Telemetry	TRACE	TelemetrySend::Scheduler::triggerSendingPings - active send task: false, immediately: true"
[task 2024-05-27T14:22:11.899Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819730011	Toolkit.Telemetry	TRACE	TelemetrySend::Scheduler::_doSendTask iteration"
[task 2024-05-27T14:22:11.899Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819730011	Toolkit.Telemetry	TRACE	TelemetrySend::Scheduler::_doSendTask - pending: 0, current: 1"
[task 2024-05-27T14:22:11.899Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819730011	Toolkit.Telemetry	TRACE	TelemetrySend::Scheduler::_doSendTask - can send - pending: 0, current: 1"
[task 2024-05-27T14:22:11.900Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819730011	Toolkit.Telemetry	TRACE	TelemetrySend::Scheduler::_doSendTask - triggering sending of 0 pings now, 0 pings waiting"
[task 2024-05-27T14:22:11.900Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819730011	Toolkit.Telemetry	TRACE	TelemetrySend::_doPing - server: http://localhost:49424, persisted: false, id: 8c48d273-fa38-49f6-bdb7-78a938c2bdf7"
[task 2024-05-27T14:22:11.900Z] 14:22:11     INFO -  "CONSOLE_MESSAGE: (info) 1716819730014	Toolkit.Telemetry	TRACE	TelemetryStorage::savePingToFile - path: /var/folders/wx/9pd2d09d01b4scy1m7mwwjf8000014/T/xpc-profile-jr24ehj5/datareporting/archived/2024-05/1716819730010.8c48d273-fa38-49f6-bdb7-78a938c2bdf7.test-ping-type.jsonlz4"
[task 2024-05-27T14:22:11.901Z] 14:22:11     INFO -  TEST-PASS | toolkit/components/telemetry/tests/unit/test_TelemetryController.js | test_simplePing - [test_simplePing : 91] type must be available. - true == true
<...>
[task 2024-05-27T14:22:12.328Z] 14:22:12     INFO -  TEST-PASS | toolkit/components/telemetry/tests/unit/test_TelemetryController.js | test_sendNewProfile - [test_sendNewProfile : 91] payload must be available. - true == true
[task 2024-05-27T14:22:12.328Z] 14:22:12  WARNING -  TEST-UNEXPECTED-FAIL | toolkit/components/telemetry/tests/unit/test_TelemetryController.js | test_sendNewProfile - [test_sendNewProfile : 94] The ping must have the correct type. - "event" == "new-profile"
[task 2024-05-27T14:22:12.328Z] 14:22:12     INFO -  /opt/worker/tasks/task_171681649062365/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/test_TelemetryController.js:checkPingFormat:94
[task 2024-05-27T14:22:12.328Z] 14:22:12     INFO -  /opt/worker/tasks/task_171681649062365/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/test_TelemetryController.js:test_sendNewProfile:771
[task 2024-05-27T14:22:12.328Z] 14:22:12     INFO -  /opt/worker/tasks/task_171681649062365/build/tests/xpcshell/head.js:_do_main:245
[task 2024-05-27T14:22:12.329Z] 14:22:12     INFO -  /opt/worker/tasks/task_171681649062365/build/tests/xpcshell/head.js:_execute_test:596
[task 2024-05-27T14:22:12.329Z] 14:22:12     INFO -  -e:null:1
[task 2024-05-27T14:22:12.329Z] 14:22:12     INFO -  exiting test
[task 2024-05-27T14:22:12.329Z] 14:22:12     INFO -  Unexpected exception NS_ERROR_ABORT:
[task 2024-05-27T14:22:12.329Z] 14:22:12     INFO -  _abort_failed_test@/opt/worker/tasks/task_171681649062365/build/tests/xpcshell/head.js:869:20
[task 2024-05-27T14:22:12.329Z] 14:22:12     INFO -  do_report_result@/opt/worker/tasks/task_171681649062365/build/tests/xpcshell/head.js:981:5
[task 2024-05-27T14:22:12.330Z] 14:22:12     INFO -  Assert<@/opt/worker/tasks/task_171681649062365/build/tests/xpcshell/head.js:70:21
[task 2024-05-27T14:22:12.330Z] 14:22:12     INFO -  Assert.prototype.report@resource://testing-common/Assert.sys.mjs:251:10
[task 2024-05-27T14:22:12.330Z] 14:22:12     INFO -  equal@resource://testing-common/Assert.sys.mjs:293:8
[task 2024-05-27T14:22:12.330Z] 14:22:12     INFO -  checkPingFormat@/opt/worker/tasks/task_171681649062365/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/test_TelemetryController.js:94:10
[task 2024-05-27T14:22:12.330Z] 14:22:12     INFO -  test_sendNewProfile@/opt/worker/tasks/task_171681649062365/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/test_TelemetryController.js:771:18
[task 2024-05-27T14:22:12.331Z] 14:22:12     INFO -  _do_main@/opt/worker/tasks/task_171681649062365/build/tests/xpcshell/head.js:245:6
[task 2024-05-27T14:22:12.331Z] 14:22:12     INFO -  _execute_test@/opt/worker/tasks/task_171681649062365/build/tests/xpcshell/head.js:596:5
[task 2024-05-27T14:22:12.331Z] 14:22:12     INFO -  @-e:1:1
[task 2024-05-27T14:22:12.331Z] 14:22:12     INFO -  exiting test
[task 2024-05-27T14:22:12.331Z] 14:22:12     INFO -  "CONSOLE_MESSAGE: (info) 1716819731840	Toolkit.Telemetry	TRACE	PingServer::defaultPingHandler() - POST http://localhost:49436/submit/telemetry/1b6df6f2-4aca-45b3-9854-98995ad1fbfa/event/XPCShell/1/default/20160315"
[task 2024-05-27T14:22:12.332Z] 14:22:12     INFO -  "CONSOLE_MESSAGE: (info) 1716819731842	Toolkit.Telemetry	TRACE	PingServer::defaultPingHandler() - POST http://localhost:49436/submit/telemetry/bf154de5-8719-4900-8ede-65a81ee6a25e/new-profile/XPCShell/1/default/20160315"
[task 2024-05-27T14:22:12.332Z] 14:22:12     INFO -  "CONSOLE_MESSAGE: (info) 1716819731842	Toolkit.Telemetry	TRACE	PingServer::defaultPingHandler() - POST http://localhost:49436/submit/telemetry/73644ecd-8d96-49fb-9ab7-cc8c71030549/event/XPCShell/1/default/20160315"
[task 2024-05-27T14:22:12.332Z] 14:22:12     INFO -  "Force a GC"
[task 2024-05-27T14:22:12.332Z] 14:22:12     INFO -  "CONSOLE_MESSAGE: (info) 1716819731853	addons.manager	DEBUG	before shutdown"
[task 2024-05-27T14:22:12.332Z] 14:22:12     INFO -  "CONSOLE_MESSAGE: (info) 1716819731853	addons.manager	DEBUG	shutdown"
[task 2024-05-27T14:22:12.333Z] 14:22:12     INFO -  "CONSOLE_MESSAGE: (info) 1716819731854	addons.manager	DEBUG	Calling shutdown blocker for XPIProvider"
[task 2024-05-27T14:22:12.333Z] 14:22:12     INFO -  "CONSOLE_MESSAGE: (info) 1716819731854	addons.xpi	DEBUG	shutdown"
[task 2024-05-27T14:22:12.333Z] 14:22:12     INFO -  "CONSOLE_MESSAGE: (info) 1716819731854	addons.xpi-utils	DEBUG	shutdown"
[task 2024-05-27T14:22:12.333Z] 14:22:12     INFO -  "CONSOLE_MESSAGE: (info) 1716819731856	addons.manager	DEBUG	Async provider shutdown done"
[task 2024-05-27T14:22:12.333Z] 14:22:12     INFO -  "CONSOLE_MESSAGE: (info) 1716819731856	Toolkit.Telemetry	TRACE	TelemetrySend::Scheduler::shutdown"
[task 2024-05-27T14:22:12.333Z] 14:22:12     INFO -  "CONSOLE_MESSAGE: (info) 1716819731857	Toolkit.Telemetry	TRACE	TelemetrySend::promisePendingPingActivity - Waiting for ping task"
[task 2024-05-27T14:22:12.334Z] 14:22:12     INFO -  PID 2787 | !!! error running onStopped callback: TypeError: callback is not a function
[task 2024-05-27T14:22:12.334Z] 14:22:12     INFO -  <<<<<<<
[task 2024-05-27T14:22:12.334Z] 14:22:12     INFO -  TEST-START | toolkit/components/telemetry/tests/unit/test_TelemetryController.js
[task 2024-05-27T14:22:14.111Z] 14:22:14  WARNING -  TEST-UNEXPECTED-FAIL | toolkit/components/telemetry/tests/unit/test_TelemetryController.js | xpcshell return code: 0
[task 2024-05-27T14:22:14.111Z] 14:22:14     INFO -  TEST-INFO took 1876ms
[task 2024-05-27T14:22:14.111Z] 14:22:14     INFO -  >>>>>>>
[task 2024-05-27T14:22:14.111Z] 14:22:14     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2024-05-27T14:22:14.111Z] 14:22:14     INFO -  (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2024-05-27T14:22:14.112Z] 14:22:14     INFO -  (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2024-05-27T14:22:14.112Z] 14:22:14     INFO -  running event loop
[task 2024-05-27T14:22:14.112Z] 14:22:14     INFO -  toolkit/components/telemetry/tests/unit/test_TelemetryController.js | Starting test_setup
[task 2024-05-27T14:22:14.112Z] 14:22:14     INFO -  (xpcshell/head.js) | test test_setup pending (2)
[task 2024-05-27T14:22:14.113Z] 14:22:14     INFO -  (xpcshell/head.js) | test run_next_test 0 finished (2)
[task 2024-05-27T14:22:14.113Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732442	addons.manager	DEBUG	Application has been upgraded"
[task 2024-05-27T14:22:14.113Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732444	addons.manager	DEBUG	Loaded provider scope for resource://gre/modules/addons/GMPProvider.sys.mjs"
[task 2024-05-27T14:22:14.113Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732446	addons.manager	DEBUG	Loaded provider scope for resource://gre/modules/addons/SitePermsAddonProvider.sys.mjs"
[task 2024-05-27T14:22:14.113Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732446	addons.manager	DEBUG	Starting provider: XPIProvider"
[task 2024-05-27T14:22:14.114Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732446	addons.xpi	DEBUG	startup"
[task 2024-05-27T14:22:14.114Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732446	addons.xpi	INFO	SystemAddonLocation directory is missing"
[task 2024-05-27T14:22:14.114Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732453	addons.xpi	INFO	Removing all system add-on upgrades."
[task 2024-05-27T14:22:14.114Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732453	addons.xpi	DEBUG	checkForChanges"
[task 2024-05-27T14:22:14.114Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732453	addons.xpi	DEBUG	Loaded add-on state: ${}"
[task 2024-05-27T14:22:14.115Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732454	addons.xpi	DEBUG	New add-on tel-system-xpi@tests.mozilla.org in app-system-defaults"
[task 2024-05-27T14:22:14.115Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732454	addons.xpi	WARN	Can't get modified time of /var/folders/wx/9pd2d09d01b4scy1m7mwwjf8000014/T/xpc-profile-zcqy_olb/sysfeatures/app0/tel-system-xpi@tests.mozilla.org.xpi"
[task 2024-05-27T14:22:14.115Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732454	addons.xpi	DEBUG	scanForChanges changed: true, state: {}"
[task 2024-05-27T14:22:14.115Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732460	addons.xpi-utils	DEBUG	Synchronously loading the add-ons database"
[task 2024-05-27T14:22:14.116Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732460	addons.xpi-utils	DEBUG	Starting async load of XPI database /var/folders/wx/9pd2d09d01b4scy1m7mwwjf8000014/T/xpc-profile-zcqy_olb/extensions.json"
[task 2024-05-27T14:22:14.116Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732462	addons.xpi-utils	DEBUG	New add-on tel-system-xpi@tests.mozilla.org installed in app-system-defaults"
[task 2024-05-27T14:22:14.117Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732463	addons.xpi-utils	WARN	addMetadata: Add-on tel-system-xpi@tests.mozilla.org is invalid: [Exception... "Component returned failure code: 0x80520012 (NS_ERROR_FILE_NOT_FOUND) [nsIFile.isFile]"  nsresult: "0x80520012 (NS_ERROR_FILE_NOT_FOUND)"  location: "JS frame :: resource://gre/modules/addons/XPIInstall.sys.mjs :: get :: line 207"  data: no] Stack trace: get()@resource://gre/modules/addons/XPIInstall.sys.mjs:207
[task 2024-05-27T14:22:14.117Z] 14:22:14     INFO -  syncLoadManifest()@resource://gre/modules/addons/XPIInstall.sys.mjs:797
[task 2024-05-27T14:22:14.117Z] 14:22:14     INFO -  addMetadata()@resource://gre/modules/addons/XPIDatabase.sys.mjs:3199
[task 2024-05-27T14:22:14.117Z] 14:22:14     INFO -  processFileChanges()@resource://gre/modules/addons/XPIDatabase.sys.mjs:3684
[task 2024-05-27T14:22:14.117Z] 14:22:14     INFO -  checkForChanges()@resource://gre/modules/addons/XPIProvider.sys.mjs:3122
[task 2024-05-27T14:22:14.118Z] 14:22:14     INFO -  startup()@resource://gre/modules/addons/XPIProvider.sys.mjs:2526
[task 2024-05-27T14:22:14.118Z] 14:22:14     INFO -  callProvider()@resource://gre/modules/AddonManager.sys.mjs:225
[task 2024-05-27T14:22:14.118Z] 14:22:14     INFO -  _startProvider()@resource://gre/modules/AddonManager.sys.mjs:534
[task 2024-05-27T14:22:14.118Z] 14:22:14     INFO -  startup()@resource://gre/modules/AddonManager.sys.mjs:747
[task 2024-05-27T14:22:14.118Z] 14:22:14     INFO -  startup()@resource://gre/modules/AddonManager.sys.mjs:3640
[task 2024-05-27T14:22:14.118Z] 14:22:14     INFO -  observe()@resource://gre/modules/amManager.sys.mjs:73
[task 2024-05-27T14:22:14.119Z] 14:22:14     INFO -  promiseStartupManager()@resource://testing-common/AddonTestUtils.sys.mjs:853
[task 2024-05-27T14:22:14.119Z] 14:22:14     INFO -  loadAddonManager()@/opt/worker/tasks/task_171681649062365/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/head.js:295
[task 2024-05-27T14:22:14.119Z] 14:22:14     INFO -  _do_main()@/opt/worker/tasks/task_171681649062365/build/tests/xpcshell/head.js:245
[task 2024-05-27T14:22:14.119Z] 14:22:14     INFO -  _execute_test()@/opt/worker/tasks/task_171681649062365/build/tests/xpcshell/head.js:596
[task 2024-05-27T14:22:14.119Z] 14:22:14     INFO -  -e:1"
[task 2024-05-27T14:22:14.119Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732464	addons.xpi-utils	WARN	Could not uninstall invalid item from locked install location"
[task 2024-05-27T14:22:14.120Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732465	addons.xpi-utils	DEBUG	Updating add-on states"
[task 2024-05-27T14:22:14.120Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732466	addons.manager	DEBUG	Registering shutdown blocker for XPIProvider"
[task 2024-05-27T14:22:14.120Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732466	addons.manager	DEBUG	Provider finished startup: XPIProvider"
[task 2024-05-27T14:22:14.120Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732467	addons.manager	DEBUG	Completed startup sequence"
[task 2024-05-27T14:22:14.120Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732477	Toolkit.Telemetry	TRACE	TelemetryEnvironment::constructor"
[task 2024-05-27T14:22:14.121Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732483	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_getGFXData - Only one display adapter detected."
[task 2024-05-27T14:22:14.121Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732485	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_updateSearchEngine - ignoring early call"
[task 2024-05-27T14:22:14.121Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732485	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_updateAddons"
[task 2024-05-27T14:22:14.121Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732487	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_updateAddons: addons differ"
[task 2024-05-27T14:22:14.122Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732490	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_startWatchingPrefs - [object Map]"
[task 2024-05-27T14:22:14.122Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732490	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_stopWatchingPrefs"
[task 2024-05-27T14:22:14.122Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732490	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_updateSearchEngine - ignoring early call"
[task 2024-05-27T14:22:14.122Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732490	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_startWatchingPrefs - [object Map]"
[task 2024-05-27T14:22:14.122Z] 14:22:14     INFO -  (xpcshell/head.js) | test run_next_test 1 pending (2)
[task 2024-05-27T14:22:14.122Z] 14:22:14     INFO -  (xpcshell/head.js) | test test_setup finished (2)
[task 2024-05-27T14:22:14.123Z] 14:22:14     INFO -  toolkit/components/telemetry/tests/unit/test_TelemetryController.js | Starting asyncSetup
[task 2024-05-27T14:22:14.123Z] 14:22:14     INFO -  (xpcshell/head.js) | test asyncSetup pending (2)
[task 2024-05-27T14:22:14.123Z] 14:22:14     INFO -  (xpcshell/head.js) | test run_next_test 1 finished (2)
[task 2024-05-27T14:22:14.123Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732492	Toolkit.Telemetry	TRACE	TelemetryController::setupTelemetry"
[task 2024-05-27T14:22:14.123Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732492	Toolkit.Telemetry	TRACE	TelemetryController::registerJsProbes - registering builtin JS probes"
[task 2024-05-27T14:22:14.123Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732492	Toolkit.Telemetry	TRACE	TelemetryController::registerScalarProbes - registering scalar builtin JS probes"
[task 2024-05-27T14:22:14.124Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732492	Toolkit.Telemetry	TRACE	TelemetryController::loadProbeDefinitions - no builtin JS probe file ScalarArtifactDefinitions.json"
[task 2024-05-27T14:22:14.124Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732493	Toolkit.Telemetry	TRACE	TelemetryReportingPolicy::setup"
[task 2024-05-27T14:22:14.124Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732493	Toolkit.Telemetry	CONFIG	TelemetryController::enableTelemetryRecording - canRecordBase:true, canRecordExtended: true"
[task 2024-05-27T14:22:14.124Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732493	Toolkit.Telemetry	TRACE	TelemetrySession::earlyInit"
[task 2024-05-27T14:22:14.125Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732493	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: toolkit.telemetry.previousBuildID"
[task 2024-05-27T14:22:14.125Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732493	Toolkit.Telemetry	INFO	TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet."
[task 2024-05-27T14:22:14.125Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732493	Toolkit.Telemetry	TRACE	UpdatePing::init - enabled: true"
[task 2024-05-27T14:22:14.125Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732494	Toolkit.Telemetry	TRACE	TelemetryController::registerEventProbes - registering builtin JS Event probes"
[task 2024-05-27T14:22:14.125Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732494	Toolkit.Telemetry	TRACE	TelemetryController::loadProbeDefinitions - no builtin JS probe file EventArtifactDefinitions.json"
[task 2024-05-27T14:22:14.126Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732500	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_onEnvironmentChange for system-info"
[task 2024-05-27T14:22:14.126Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732501	Toolkit.Telemetry	TRACE	ClientID::_doLoadClientID"
[task 2024-05-27T14:22:14.126Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732502	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: toolkit.telemetry.cachedClientID"
[task 2024-05-27T14:22:14.126Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732502	Toolkit.Telemetry	TRACE	ClientID::_saveClientID"
[task 2024-05-27T14:22:14.127Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732503	Toolkit.Telemetry	TRACE	ClientID::_doLoadClientID: New client ID loaded and persisted."
[task 2024-05-27T14:22:14.127Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732503	Toolkit.Telemetry	TRACE	TelemetrySend::setup"
[task 2024-05-27T14:22:14.127Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732503	Toolkit.Telemetry	INFO	TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet."
[task 2024-05-27T14:22:14.127Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732503	Toolkit.Telemetry	TRACE	TelemetryStorage::_scanPendingPings"
[task 2024-05-27T14:22:14.127Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732503	Toolkit.Telemetry	TRACE	TelemetryStorage::_migrateAppDataPings"
[task 2024-05-27T14:22:14.128Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732503	Toolkit.Telemetry	TRACE	TelemetryStorage::_iterateAppDataPings"
[task 2024-05-27T14:22:14.128Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732503	Toolkit.Telemetry	TRACE	TelemetryStorage::_iterateAppDataPings - userApplicationDataDir is not defined. Is this a test?"
[task 2024-05-27T14:22:14.128Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732504	Toolkit.Telemetry	INFO	TelemetrySend::_checkPendingPings - pending ping count: 0"
[task 2024-05-27T14:22:14.128Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732504	Toolkit.Telemetry	TRACE	TelemetrySend::_checkPendingPings - no pending pings"
[task 2024-05-27T14:22:14.129Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732504	Toolkit.Telemetry	TRACE	TelemetryStorage::_enforcePendingPingsQuota"
[task 2024-05-27T14:22:14.129Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732504	Toolkit.Telemetry	TRACE	TelemetrySend::Scheduler::triggerSendingPings - active send task: false, immediately: true"
[task 2024-05-27T14:22:14.129Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732504	Toolkit.Telemetry	TRACE	TelemetrySend::Scheduler::_doSendTask iteration"
[task 2024-05-27T14:22:14.129Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732504	Toolkit.Telemetry	TRACE	TelemetrySend::Scheduler::_doSendTask - pending: 0, current: 0"
[task 2024-05-27T14:22:14.130Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732504	Toolkit.Telemetry	TRACE	TelemetrySend::Scheduler::_doSendTask - can send - pending: 0, current: 0"
[task 2024-05-27T14:22:14.130Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732504	Toolkit.Telemetry	TRACE	TelemetrySend::Scheduler::_doSendTask - no pending pings, bailing out"
[task 2024-05-27T14:22:14.130Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732504	Toolkit.Telemetry	TRACE	TelemetrySession::delayedInit"
[task 2024-05-27T14:22:14.130Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732504	Toolkit.Telemetry	TRACE	TelemetryStorage::_popAndPerformQueuedOperation - Performing queued operation."
[task 2024-05-27T14:22:14.131Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732505	Toolkit.Telemetry	INFO	TelemetryStorage::_loadSessionData - can not load session data file: NotFoundError: Could not open `/var/folders/wx/9pd2d09d01b4scy1m7mwwjf8000014/T/xpc-profile-zcqy_olb/datareporting/session-state.json': file does not exist (NS_ERROR_FILE_NOT_FOUND) Stack trace: _do_main()@/opt/worker/tasks/task_171681649062365/build/tests/xpcshell/head.js:245
[task 2024-05-27T14:22:14.131Z] 14:22:14     INFO -  _execute_test()@/opt/worker/tasks/task_171681649062365/build/tests/xpcshell/head.js:596
[task 2024-05-27T14:22:14.131Z] 14:22:14     INFO -  -e:1"
[task 2024-05-27T14:22:14.131Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732505	Toolkit.Telemetry	TRACE	TelemetryStorage::_popAndPerformQueuedOperation - Performing queued operation."
[task 2024-05-27T14:22:14.132Z] 14:22:14     INFO -  (xpcshell/head.js) | test run_next_test 2 pending (2)
[task 2024-05-27T14:22:14.132Z] 14:22:14     INFO -  (xpcshell/head.js) | test asyncSetup finished (2)
[task 2024-05-27T14:22:14.132Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732505	addons.xpi-utils	DEBUG	XPI Database saved, setting schema version preference to 36"
[task 2024-05-27T14:22:14.132Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732506	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: extensions.databaseSchema"
[task 2024-05-27T14:22:14.133Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732506	Toolkit.Telemetry	TRACE	TelemetryStorage::loadPingfile - unreadable ping /var/folders/wx/9pd2d09d01b4scy1m7mwwjf8000014/T/xpc-profile-zcqy_olb/datareporting/aborted-session-ping: NotFoundError: Could not open `/var/folders/wx/9pd2d09d01b4scy1m7mwwjf8000014/T/xpc-profile-zcqy_olb/datareporting/aborted-session-ping': file does not exist (NS_ERROR_FILE_NOT_FOUND) Stack trace: _do_main()@/opt/worker/tasks/task_171681649062365/build/tests/xpcshell/head.js:245
[task 2024-05-27T14:22:14.133Z] 14:22:14     INFO -  _execute_test()@/opt/worker/tasks/task_171681649062365/build/tests/xpcshell/head.js:596
[task 2024-05-27T14:22:14.133Z] 14:22:14     INFO -  -e:1"
[task 2024-05-27T14:22:14.133Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732506	Toolkit.Telemetry	TRACE	TelemetryStorage::loadAbortedSessionPing - no such file"
[task 2024-05-27T14:22:14.134Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732506	Toolkit.Telemetry	TRACE	TelemetryController::checkAbortedSessionPing - found aborted-session ping: false"
[task 2024-05-27T14:22:14.134Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732506	Toolkit.Telemetry	TRACE	TelemetryEnvironment::registerChangeListener for TelemetrySession::onEnvironmentChange"
[task 2024-05-27T14:22:14.134Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732506	Toolkit.Telemetry	TRACE	TelemetryScheduler::init"
[task 2024-05-27T14:22:14.134Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732506	Toolkit.Telemetry	TRACE	TelemetryScheduler::_rescheduleTimeout - isUserIdle: false"
[task 2024-05-27T14:22:14.135Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732507	Toolkit.Telemetry	TRACE	TelemetryScheduler::_rescheduleTimeout - scheduling next tick for Mon May 27 2024 14:27:12 GMT+0000 (Greenwich Mean Time)"
[task 2024-05-27T14:22:14.135Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732507	Toolkit.Telemetry	TRACE	TelemetryStorage::cleanArchiveTask"
[task 2024-05-27T14:22:14.135Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732507	Toolkit.Telemetry	TRACE	TelemetryStorage::removeFHRDatabase"
[task 2024-05-27T14:22:14.135Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732507	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: app.update.lastUpdateTime.telemetry_modules_ping"
[task 2024-05-27T14:22:14.136Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732508	Toolkit.Telemetry	TRACE	TelemetryEventPing::::Starting up."
[task 2024-05-27T14:22:14.136Z] 14:22:14     INFO -  toolkit/components/telemetry/tests/unit/test_TelemetryController.js | Starting test_overwritePing
[task 2024-05-27T14:22:14.136Z] 14:22:14     INFO -  (xpcshell/head.js) | test test_overwritePing pending (2)
[task 2024-05-27T14:22:14.136Z] 14:22:14     INFO -  (xpcshell/head.js) | test run_next_test 2 finished (2)
[task 2024-05-27T14:22:14.136Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732510	Toolkit.Telemetry	TRACE	TelemetryStorage::savePingToFile - path: /var/folders/wx/9pd2d09d01b4scy1m7mwwjf8000014/T/xpc-profile-zcqy_olb/saved-telemetry-pings/foo"
[task 2024-05-27T14:22:14.137Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732511	Toolkit.Telemetry	TRACE	TelemetryStorage::savePingToFile - path: /var/folders/wx/9pd2d09d01b4scy1m7mwwjf8000014/T/xpc-profile-zcqy_olb/saved-telemetry-pings/foo"
[task 2024-05-27T14:22:14.137Z] 14:22:14     INFO -  (xpcshell/head.js) | test run_next_test 3 pending (2)
[task 2024-05-27T14:22:14.137Z] 14:22:14     INFO -  (xpcshell/head.js) | test test_overwritePing finished (2)
[task 2024-05-27T14:22:14.137Z] 14:22:14     INFO -  toolkit/components/telemetry/tests/unit/test_TelemetryController.js | Starting test_simplePing
[task 2024-05-27T14:22:14.137Z] 14:22:14     INFO -  (xpcshell/head.js) | test test_simplePing pending (2)
[task 2024-05-27T14:22:14.138Z] 14:22:14     INFO -  (xpcshell/head.js) | test run_next_test 3 finished (2)
[task 2024-05-27T14:22:14.138Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732517	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: toolkit.telemetry.server"
[task 2024-05-27T14:22:14.138Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732517	Toolkit.Telemetry	TRACE	TelemetrySend::setServer: http://localhost:49458"
[task 2024-05-27T14:22:14.139Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732517	Toolkit.Telemetry	TRACE	TelemetryController::submitExternalPing - type: test-ping-type, aOptions: {"addClientId":false,"addEnvironment":false,"usePingSender":false}"
[task 2024-05-27T14:22:14.139Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732517	Toolkit.Telemetry	TRACE	TelemetryController::assemblePing - Type test-ping-type, aOptions {"addClientId":false,"addEnvironment":false,"usePingSender":false}"
[task 2024-05-27T14:22:14.139Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732517	Toolkit.Telemetry	TRACE	TelemetryController::submitExternalPing - ping assembled, id: e3b0f7e2-ca90-4e5b-b82c-5f0303404507"
[task 2024-05-27T14:22:14.139Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732517	Toolkit.Telemetry	TRACE	TelemetrySend::submitPing - ping id: e3b0f7e2-ca90-4e5b-b82c-5f0303404507, options: {"usePingSender":false}"
[task 2024-05-27T14:22:14.140Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732517	Toolkit.Telemetry	INFO	TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet."
[task 2024-05-27T14:22:14.140Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732517	Toolkit.Telemetry	TRACE	TelemetrySend::submitPing - can send pings, trying to send now"
[task 2024-05-27T14:22:14.140Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732517	Toolkit.Telemetry	TRACE	TelemetrySend::Scheduler::triggerSendingPings - active send task: false, immediately: true"
[task 2024-05-27T14:22:14.140Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732517	Toolkit.Telemetry	TRACE	TelemetrySend::Scheduler::_doSendTask iteration"
[task 2024-05-27T14:22:14.141Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732517	Toolkit.Telemetry	TRACE	TelemetrySend::Scheduler::_doSendTask - pending: 0, current: 1"
[task 2024-05-27T14:22:14.141Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732517	Toolkit.Telemetry	TRACE	TelemetrySend::Scheduler::_doSendTask - can send - pending: 0, current: 1"
[task 2024-05-27T14:22:14.141Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732517	Toolkit.Telemetry	TRACE	TelemetrySend::Scheduler::_doSendTask - triggering sending of 0 pings now, 0 pings waiting"
[task 2024-05-27T14:22:14.142Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732517	Toolkit.Telemetry	TRACE	TelemetrySend::_doPing - server: http://localhost:49458, persisted: false, id: e3b0f7e2-ca90-4e5b-b82c-5f0303404507"
[task 2024-05-27T14:22:14.142Z] 14:22:14     INFO -  "CONSOLE_MESSAGE: (info) 1716819732520	Toolkit.Telemetry	TRACE	TelemetryStorage::savePingToFile - path: /var/folders/wx/9pd2d09d01b4scy1m7mwwjf8000014/T/xpc-profile-zcqy_olb/datareporting/archived/2024-05/1716819732517.e3b0f7e2-ca90-4e5b-b82c-5f0303404507.test-ping-type.jsonlz4"
[task 2024-05-27T14:22:14.142Z] 14:22:14     INFO -  TEST-PASS | toolkit/components/telemetry/tests/unit/test_TelemetryController.js | test_simplePing - [test_simplePing : 91] type must be available. - true == true

:mpohle, since you are the author of the regressor, bug 1811374, could you take a look?

For more information, please visit BugBot documentation.

Flags: needinfo?(mpohle)

This should be fixed by the backout of bug 1811374: https://hg.mozilla.org/integration/autoland/rev/96c95ccee3db360d38389f87acf07312f4081b32

Status: NEW → RESOLVED
Closed: 1 year ago
Flags: needinfo?(mpohle)
Resolution: --- → FIXED
status-firefox126: --- → unaffected
status-firefox127: --- → unaffected
status-firefox128: --- → fixed
status-firefox-esr115: --- → unaffected
Target Milestone: --- → 128 Branch
You need to log in before you can comment on or make changes to this bug.