1686295 - Intermittent toolkit/components/telemetry/tests/unit/test_TelemetrySession.js | sessionTimeExcludingAndIncludingSuspend - [sessionTimeExcludingAndIncludingSuspend : 649] The uptime with suspend must always been greater or equal to the uptime

Status: RESOLVED FIXED

(Toolkit :: Telemetry, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: abutkovits [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=326469049&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/LffXqICzR_6xPZUbR3IrEw/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/LffXqICzR_6xPZUbR3IrEw/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

---

[task 2021-01-12T16:39:10.553Z] 16:39:10     INFO -  TEST-START | toolkit/components/telemetry/tests/unit/test_TelemetrySession.js
[task 2021-01-12T16:40:49.352Z] 16:40:49     INFO -  TEST-PASS | toolkit/components/telemetry/tests/unit/test_TelemetrySession.js | took 98808ms
[task 2021-01-12T16:40:49.369Z] 16:40:49     INFO -  TEST-START | toolkit/components/telemetry/tests/unit/test_TelemetrySession.js
[task 2021-01-12T16:40:54.773Z] 16:40:54  WARNING -  TEST-UNEXPECTED-FAIL | toolkit/components/telemetry/tests/unit/test_TelemetrySession.js | xpcshell return code: 0
[task 2021-01-12T16:40:54.774Z] 16:40:54     INFO -  TEST-INFO took 5406ms
[task 2021-01-12T16:40:54.774Z] 16:40:54     INFO -  >>>>>>>
[task 2021-01-12T16:40:54.774Z] 16:40:54     INFO -  PID 1627 | *** You are running in chaos test mode. See ChaosMode.h. ***
[task 2021-01-12T16:40:54.774Z] 16:40:54     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2021-01-12T16:40:54.774Z] 16:40:54     INFO -  (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2021-01-12T16:40:54.774Z] 16:40:54     INFO -  (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2021-01-12T16:40:54.776Z] 16:40:54     INFO -  running event loop
[task 2021-01-12T16:40:54.776Z] 16:40:54     INFO -  toolkit/components/telemetry/tests/unit/test_TelemetrySession.js | Starting test_setup
[task 2021-01-12T16:40:54.776Z] 16:40:54     INFO -  (xpcshell/head.js) | test test_setup pending (2)
[task 2021-01-12T16:40:54.776Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469649845	addons.manager	DEBUG	Application has been upgraded"
[task 2021-01-12T16:40:54.776Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469649851	addons.manager	DEBUG	Loaded provider scope for resource://gre/modules/addons/XPIProvider.jsm: ["XPIProvider", "XPIInternal"]"
[task 2021-01-12T16:40:54.776Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469649855	addons.manager	DEBUG	Loaded provider scope for resource://gre/modules/addons/GMPProvider.jsm"
[task 2021-01-12T16:40:54.776Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469649860	addons.manager	DEBUG	Loaded provider scope for resource://gre/modules/addons/PluginProvider.jsm"
[task 2021-01-12T16:40:54.777Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469649863	addons.manager	DEBUG	Starting provider: XPIProvider"
[task 2021-01-12T16:40:54.777Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469649865	addons.xpi	DEBUG	startup"
[task 2021-01-12T16:40:54.777Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469649868	addons.xpi	INFO	SystemAddonLocation directory is missing"
[task 2021-01-12T16:40:54.777Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469649880	addons.xpi	INFO	Removing all system add-on upgrades."
[task 2021-01-12T16:40:54.778Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469649885	addons.xpi	DEBUG	checkForChanges"
[task 2021-01-12T16:40:54.778Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469649890	addons.xpi	DEBUG	Loaded add-on state: ${}"
[task 2021-01-12T16:40:54.778Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469649897	addons.xpi	DEBUG	New add-on [e-mail] in app-system-defaults"
[task 2021-01-12T16:40:54.778Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469649903	addons.xpi	WARN	Can't get modified time of /var/folders/v4/r817j8t53wvbls6qlkwj9h_8000017/T/xpc-profile-wb5pbu/sysfeatures/app0/[e-mail]"
[task 2021-01-12T16:40:54.778Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469649906	addons.xpi	DEBUG	scanForChanges changed: true, state: {}"
[task 2021-01-12T16:40:54.780Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469649916	addons.xpi-utils	DEBUG	Synchronously loading the add-ons database"
[task 2021-01-12T16:40:54.780Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469649925	addons.xpi-utils	DEBUG	Starting async load of XPI database /var/folders/v4/r817j8t53wvbls6qlkwj9h_8000017/T/xpc-profile-wb5pbu/extensions.json"
[task 2021-01-12T16:40:54.780Z] 16:40:54     INFO -  (xpcshell/head.js) | test run_next_test 0 finished (2)
[task 2021-01-12T16:40:54.780Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469651121	addons.xpi-utils	DEBUG	New add-on [e-mail] installed in app-system-defaults"
[task 2021-01-12T16:40:54.780Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469651128	addons.xpi-utils	WARN	addMetadata: Add-on [e-mail] is invalid: [Exception... "Component returned failure code: 0x80520006 (NS_ERROR_FILE_TARGET_DOES_NOT_EXIST) [nsIFile.isFile]"  nsresult: "0x80520006 (NS_ERROR_FILE_TARGET_DOES_NOT_EXIST)"  location: "JS frame :: resource://gre/modules/addons/XPIInstall.jsm :: get :: line 232"  data: no] Stack trace: get()@resource://gre/modules/addons/XPIInstall.jsm:232
[task 2021-01-12T16:40:54.780Z] 16:40:54     INFO -  syncLoadManifest()@resource://gre/modules/addons/XPIInstall.jsm:751
[task 2021-01-12T16:40:54.780Z] 16:40:54     INFO -  addMetadata()@resource://gre/modules/addons/XPIDatabase.jsm:2827
[task 2021-01-12T16:40:54.781Z] 16:40:54     INFO -  processFileChanges()@resource://gre/modules/addons/XPIDatabase.jsm:3292
[task 2021-01-12T16:40:54.781Z] 16:40:54     INFO -  checkForChanges()@resource://gre/modules/addons/XPIProvider.jsm:3027
[task 2021-01-12T16:40:54.781Z] 16:40:54     INFO -  startup()@resource://gre/modules/addons/XPIProvider.jsm:2474
[task 2021-01-12T16:40:54.781Z] 16:40:54     INFO -  callProvider()@resource://gre/modules/AddonManager.jsm:230
[task 2021-01-12T16:40:54.781Z] 16:40:54     INFO -  _startProvider()@resource://gre/modules/AddonManager.jsm:601
[task 2021-01-12T16:40:54.781Z] 16:40:54     INFO -  startup()@resource://gre/modules/AddonManager.jsm:825
[task 2021-01-12T16:40:54.781Z] 16:40:54     INFO -  startup()@resource://gre/modules/AddonManager.jsm:3530
[task 2021-01-12T16:40:54.782Z] 16:40:54     INFO -  observe()@resource://gre/modules/addonManager.js:87
[task 2021-01-12T16:40:54.782Z] 16:40:54     INFO -  promiseStartupManager()@resource://testing-common/AddonTestUtils.jsm:975
[task 2021-01-12T16:40:54.782Z] 16:40:54     INFO -  loadAddonManager()@/Users/cltbld/tasks/task_1610469274/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/head.js:309
[task 2021-01-12T16:40:54.782Z] 16:40:54     INFO -  test_setup()@/Users/cltbld/tasks/task_1610469274/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/test_TelemetrySession.js:539
[task 2021-01-12T16:40:54.782Z] 16:40:54     INFO -  _run_next_test/<()@/Users/cltbld/tasks/task_1610469274/build/tests/xpcshell/head.js:1620
[task 2021-01-12T16:40:54.782Z] 16:40:54     INFO -  _run_next_test()@/Users/cltbld/tasks/task_1610469274/build/tests/xpcshell/head.js:1620
[task 2021-01-12T16:40:54.782Z] 16:40:54     INFO -  run()@/Users/cltbld/tasks/task_1610469274/build/tests/xpcshell/head.js:767
[task 2021-01-12T16:40:54.783Z] 16:40:54     INFO -  _do_main()@/Users/cltbld/tasks/task_1610469274/build/tests/xpcshell/head.js:239
[task 2021-01-12T16:40:54.783Z] 16:40:54     INFO -  _execute_test()@/Users/cltbld/tasks/task_1610469274/build/tests/xpcshell/head.js:567
[task 2021-01-12T16:40:54.783Z] 16:40:54     INFO -  -e:1"
[task 2021-01-12T16:40:54.783Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469651137	addons.xpi-utils	WARN	Could not uninstall invalid item from locked install location"
[task 2021-01-12T16:40:54.783Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469651147	addons.xpi-utils	DEBUG	Updating add-on states"
[task 2021-01-12T16:40:54.783Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469651155	addons.xpi-utils	DEBUG	Synchronously loading the add-ons database"
[task 2021-01-12T16:40:54.792Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469651178	addons.manager	DEBUG	Registering shutdown blocker for XPIProvider"
[task 2021-01-12T16:40:54.792Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469651182	addons.manager	DEBUG	Provider finished startup: XPIProvider"
[task 2021-01-12T16:40:54.792Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469651183	addons.manager	DEBUG	Starting provider: PluginProvider"
[task 2021-01-12T16:40:54.792Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469651184	addons.manager	DEBUG	Registering shutdown blocker for PluginProvider"
[task 2021-01-12T16:40:54.792Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469651189	addons.manager	DEBUG	Provider finished startup: PluginProvider"
[task 2021-01-12T16:40:54.792Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469651192	addons.manager	DEBUG	Completed startup sequence"
[task 2021-01-12T16:40:54.792Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469651220	Toolkit.Telemetry	TRACE	TelemetryEnvironment::constructor"
[task 2021-01-12T16:40:54.792Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469651324	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_getGFXData - Only one display adapter detected."
[task 2021-01-12T16:40:54.793Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469651328	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_updateSearchEngine - ignoring early call"
[task 2021-01-12T16:40:54.793Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469651337	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_updateAddons"
[task 2021-01-12T16:40:54.793Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469651349	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_updateAddons: addons differ"
[task 2021-01-12T16:40:54.793Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469651590	addons.xpi-utils	DEBUG	XPI Database saved, setting schema version preference to 33"
[task 2021-01-12T16:40:54.793Z] 16:40:54     INFO -  TEST-PASS | toolkit/components/telemetry/tests/unit/test_TelemetrySession.js | test_setup - [test_setup : 554] true == true
[task 2021-01-12T16:40:54.793Z] 16:40:54     INFO -  TEST-PASS | toolkit/components/telemetry/tests/unit/test_TelemetrySession.js | test_setup - [test_setup : 567] true == true
[task 2021-01-12T16:40:54.793Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469652535	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_startWatchingPrefs - [object Map]"
[task 2021-01-12T16:40:54.793Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469652540	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_stopWatchingPrefs"
[task 2021-01-12T16:40:54.793Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469652544	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_updateSearchEngine - ignoring early call"
[task 2021-01-12T16:40:54.794Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469652545	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_startWatchingPrefs - [object Map]"
[task 2021-01-12T16:40:54.794Z] 16:40:54     INFO -  (xpcshell/head.js) | test run_next_test 1 pending (2)
[task 2021-01-12T16:40:54.794Z] 16:40:54     INFO -  (xpcshell/head.js) | test test_setup finished (2)
[task 2021-01-12T16:40:54.794Z] 16:40:54     INFO -  toolkit/components/telemetry/tests/unit/test_TelemetrySession.js | Starting asyncSetup
[task 2021-01-12T16:40:54.794Z] 16:40:54     INFO -  (xpcshell/head.js) | test asyncSetup pending (2)
[task 2021-01-12T16:40:54.794Z] 16:40:54     INFO -  (xpcshell/head.js) | test run_next_test 1 finished (2)
[task 2021-01-12T16:40:54.794Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469652588	Toolkit.Telemetry	TRACE	TelemetryController::setupTelemetry"
[task 2021-01-12T16:40:54.794Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469652595	Toolkit.Telemetry	TRACE	TelemetryController::registerJsProbes - registering builtin JS probes"
[task 2021-01-12T16:40:54.795Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469652602	Toolkit.Telemetry	TRACE	TelemetryController::registerScalarProbes - registering scalar builtin JS probes"
[task 2021-01-12T16:40:54.795Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469652605	Toolkit.Telemetry	TRACE	TelemetryController::loadProbeDefinitions - no builtin JS probe file ScalarArtifactDefinitions.json"
[task 2021-01-12T16:40:54.795Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469652608	Toolkit.Telemetry	TRACE	TelemetryReportingPolicy::setup"
[task 2021-01-12T16:40:54.795Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469652613	Toolkit.Telemetry	CONFIG	TelemetryController::enableTelemetryRecording - canRecordBase:true, canRecordExtended: true"
[task 2021-01-12T16:40:54.795Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469652614	Toolkit.Telemetry	TRACE	TelemetrySession::earlyInit"
[task 2021-01-12T16:40:54.795Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469652623	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: toolkit.telemetry.previousBuildID"
[task 2021-01-12T16:40:54.795Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469652632	Toolkit.Telemetry	INFO	TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet."
[task 2021-01-12T16:40:54.795Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469652641	Toolkit.Telemetry	TRACE	UpdatePing::init - enabled: true"
[task 2021-01-12T16:40:54.795Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469652647	Toolkit.Telemetry	TRACE	TelemetryController::registerEventProbes - registering builtin JS Event probes"
[task 2021-01-12T16:40:54.796Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469652656	Toolkit.Telemetry	TRACE	TelemetryController::loadProbeDefinitions - no builtin JS probe file EventArtifactDefinitions.json"
[task 2021-01-12T16:40:54.796Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469652728	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_onEnvironmentChange for system-info"
[task 2021-01-12T16:40:54.796Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469652738	Toolkit.Telemetry	TRACE	ClientID::_doLoadClientIDs"
[task 2021-01-12T16:40:54.796Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469652762	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: toolkit.telemetry.cachedClientID"
[task 2021-01-12T16:40:54.796Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469652768	Toolkit.Telemetry	TRACE	ClientID::_saveClientIDs"
[task 2021-01-12T16:40:54.796Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469652799	Toolkit.Telemetry	TRACE	ClientID::_doLoadClientIDs: New client IDs loaded and persisted."
[task 2021-01-12T16:40:54.796Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469652804	Toolkit.Telemetry	TRACE	TelemetrySend::setup"
[task 2021-01-12T16:40:54.796Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469652808	Toolkit.Telemetry	INFO	TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet."
[task 2021-01-12T16:40:54.797Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469652817	Toolkit.Telemetry	TRACE	TelemetryStorage::_scanPendingPings"
[task 2021-01-12T16:40:54.797Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469652819	Toolkit.Telemetry	TRACE	TelemetryStorage::_migrateAppDataPings"
[task 2021-01-12T16:40:54.797Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469652826	Toolkit.Telemetry	TRACE	TelemetryStorage::_iterateAppDataPings"
[task 2021-01-12T16:40:54.797Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469652833	Toolkit.Telemetry	TRACE	TelemetryStorage::_iterateAppDataPings - userApplicationDataDir is not defined. Is this a test?"
[task 2021-01-12T16:40:54.797Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469652963	Toolkit.Telemetry	INFO	TelemetrySend::_checkPendingPings - pending ping count: 0"
[task 2021-01-12T16:40:54.797Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469652964	Toolkit.Telemetry	TRACE	TelemetrySend::_checkPendingPings - no pending pings"
[task 2021-01-12T16:40:54.797Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469652970	Toolkit.Telemetry	TRACE	TelemetryStorage::_enforcePendingPingsQuota"
[task 2021-01-12T16:40:54.797Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469652976	Toolkit.Telemetry	TRACE	TelemetrySend::Scheduler::triggerSendingPings - active send task: false, immediately: true"
[task 2021-01-12T16:40:54.797Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469652984	Toolkit.Telemetry	TRACE	TelemetrySend::Scheduler::_doSendTask iteration"
[task 2021-01-12T16:40:54.797Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469652989	Toolkit.Telemetry	TRACE	TelemetrySend::Scheduler::_doSendTask - pending: 0, current: 0"
[task 2021-01-12T16:40:54.798Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469652990	Toolkit.Telemetry	TRACE	TelemetrySend::Scheduler::_doSendTask - can send - pending: 0, current: 0"
[task 2021-01-12T16:40:54.798Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469652999	Toolkit.Telemetry	TRACE	TelemetrySend::Scheduler::_doSendTask - no pending pings, bailing out"
[task 2021-01-12T16:40:54.798Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653003	Toolkit.Telemetry	TRACE	TelemetrySession::delayedInit"
[task 2021-01-12T16:40:54.798Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653005	Toolkit.Telemetry	TRACE	TelemetryStorage::_popAndPerformQueuedOperation - Performing queued operation."
[task 2021-01-12T16:40:54.798Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653087	Toolkit.Telemetry	INFO	TelemetryStorage::_loadSessionData - can not load session data file: {"operation":"open","path":"/var/folders/v4/r817j8t53wvbls6qlkwj9h_8000017/T/xpc-profile-wb5pbu/datareporting/session-state.json","unixErrno":2}"
[task 2021-01-12T16:40:54.798Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653090	Toolkit.Telemetry	TRACE	TelemetryStorage::_popAndPerformQueuedOperation - Performing queued operation."
[task 2021-01-12T16:40:54.798Z] 16:40:54     INFO -  (xpcshell/head.js) | test run_next_test 2 pending (2)
[task 2021-01-12T16:40:54.798Z] 16:40:54     INFO -  (xpcshell/head.js) | test asyncSetup finished (2)
[task 2021-01-12T16:40:54.799Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653161	Toolkit.Telemetry	TRACE	TelemetryStorage::loadPingfile - unreadable ping /var/folders/v4/r817j8t53wvbls6qlkwj9h_8000017/T/xpc-profile-wb5pbu/datareporting/aborted-session-ping: {"operation":"open","path":"/var/folders/v4/r817j8t53wvbls6qlkwj9h_8000017/T/xpc-profile-wb5pbu/datareporting/aborted-session-ping","unixErrno":2}"
[task 2021-01-12T16:40:54.799Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653165	Toolkit.Telemetry	TRACE	TelemetryStorage::loadAbortedSessionPing - no such file"
[task 2021-01-12T16:40:54.799Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653168	Toolkit.Telemetry	TRACE	TelemetryController::checkAbortedSessionPing - found aborted-session ping: false"
[task 2021-01-12T16:40:54.799Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653168	Toolkit.Telemetry	TRACE	TelemetryEnvironment::registerChangeListener for TelemetrySession::onEnvironmentChange"
[task 2021-01-12T16:40:54.799Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653173	Toolkit.Telemetry	TRACE	TelemetryScheduler::init"
[task 2021-01-12T16:40:54.799Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653178	Toolkit.Telemetry	TRACE	TelemetryScheduler::_rescheduleTimeout - isUserIdle: false"
[task 2021-01-12T16:40:54.799Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653187	Toolkit.Telemetry	TRACE	TelemetryScheduler::_rescheduleTimeout - scheduling next tick for Tue Jan 12 2021 16:45:53 GMT+0000 (Greenwich Mean Time)"
[task 2021-01-12T16:40:54.800Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653204	Toolkit.Telemetry	TRACE	TelemetryStorage::cleanArchiveTask"
[task 2021-01-12T16:40:54.800Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653208	Toolkit.Telemetry	TRACE	TelemetryStorage::removeFHRDatabase"
[task 2021-01-12T16:40:54.800Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653214	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: app.update.lastUpdateTime.telemetry_modules_ping"
[task 2021-01-12T16:40:54.800Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653217	Toolkit.Telemetry	TRACE	TelemetryEventPing::::Starting up."
[task 2021-01-12T16:40:54.800Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653218	Toolkit.Telemetry	TRACE	TelemetryPrioPing::Starting up."
[task 2021-01-12T16:40:54.800Z] 16:40:54     INFO -  toolkit/components/telemetry/tests/unit/test_TelemetrySession.js | Starting test_expiredHistogram
[task 2021-01-12T16:40:54.800Z] 16:40:54     INFO -  (xpcshell/head.js) | test test_expiredHistogram pending (2)
[task 2021-01-12T16:40:54.800Z] 16:40:54     INFO -  TEST-PASS | toolkit/components/telemetry/tests/unit/test_TelemetrySession.js | test_expiredHistogram - [test_expiredHistogram : 594] "undefined" == "undefined"
[task 2021-01-12T16:40:54.800Z] 16:40:54     INFO -  (xpcshell/head.js) | test run_next_test 2 finished (2)
[task 2021-01-12T16:40:54.800Z] 16:40:54     INFO -  (xpcshell/head.js) | test run_next_test 3 pending (2)
[task 2021-01-12T16:40:54.801Z] 16:40:54     INFO -  (xpcshell/head.js) | test test_expiredHistogram finished (2)
[task 2021-01-12T16:40:54.801Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653287	Toolkit.Telemetry	TRACE	TelemetrySession::getPayload - clearSubsession: false"
[task 2021-01-12T16:40:54.801Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653291	Toolkit.Telemetry	TRACE	TelemetrySession::getSessionPayload - reason: gather-payload, clearSubsession: false"
[task 2021-01-12T16:40:54.801Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653297	Toolkit.Telemetry	TRACE	TelemetrySession::assemblePayloadWithMeasurements - reason: gather-payload, submitting subsession data: false"
[task 2021-01-12T16:40:54.801Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653299	Toolkit.Telemetry	TRACE	TelemetrySession::getScalars - We only support scalars in subsessions."
[task 2021-01-12T16:40:54.801Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653299	Toolkit.Telemetry	TRACE	TelemetrySession::getScalars - We only support scalars in subsessions."
[task 2021-01-12T16:40:54.801Z] 16:40:54     INFO -  toolkit/components/telemetry/tests/unit/test_TelemetrySession.js | Starting sessionTimeExcludingAndIncludingSuspend
[task 2021-01-12T16:40:54.801Z] 16:40:54     INFO -  (xpcshell/head.js) | test sessionTimeExcludingAndIncludingSuspend pending (2)
[task 2021-01-12T16:40:54.802Z] 16:40:54     INFO -  (xpcshell/head.js) | test run_next_test 3 finished (2)
[task 2021-01-12T16:40:54.802Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653364	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: toolkit.telemetry.testing.overrideProductsCheck"
[task 2021-01-12T16:40:54.802Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653371	Toolkit.Telemetry	TRACE	TelemetryController::setupTelemetry"
[task 2021-01-12T16:40:54.802Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653375	Toolkit.Telemetry	TRACE	TelemetryController::registerJsProbes - registering builtin JS probes"
[task 2021-01-12T16:40:54.802Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653377	Toolkit.Telemetry	TRACE	TelemetryController::registerScalarProbes - registering scalar builtin JS probes"
[task 2021-01-12T16:40:54.802Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653378	Toolkit.Telemetry	TRACE	TelemetryController::loadProbeDefinitions - no builtin JS probe file ScalarArtifactDefinitions.json"
[task 2021-01-12T16:40:54.802Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653381	Toolkit.Telemetry	TRACE	TelemetryReportingPolicy::setup"
[task 2021-01-12T16:40:54.802Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653383	Toolkit.Telemetry	CONFIG	TelemetryController::enableTelemetryRecording - canRecordBase:true, canRecordExtended: true"
[task 2021-01-12T16:40:54.802Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653391	Toolkit.Telemetry	TRACE	TelemetrySession::earlyInit"
[task 2021-01-12T16:40:54.803Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653393	Toolkit.Telemetry	INFO	TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet."
[task 2021-01-12T16:40:54.803Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653400	Toolkit.Telemetry	TRACE	UpdatePing::init - enabled: true"
[task 2021-01-12T16:40:54.803Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653401	Toolkit.Telemetry	TRACE	TelemetrySend::reset"
[task 2021-01-12T16:40:54.803Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653406	Toolkit.Telemetry	TRACE	TelemetrySend::Scheduler::reset"
[task 2021-01-12T16:40:54.803Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653409	Toolkit.Telemetry	TRACE	TelemetrySend::Scheduler::shutdown"
[task 2021-01-12T16:40:54.803Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653414	Toolkit.Telemetry	TRACE	TelemetryController::registerEventProbes - registering builtin JS Event probes"
[task 2021-01-12T16:40:54.803Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653419	Toolkit.Telemetry	TRACE	TelemetryController::loadProbeDefinitions - no builtin JS probe file EventArtifactDefinitions.json"
[task 2021-01-12T16:40:54.804Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653420	Toolkit.Telemetry	TRACE	TelemetrySend::Scheduler::start"
[task 2021-01-12T16:40:54.804Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653574	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_onEnvironmentChange for system-info"
[task 2021-01-12T16:40:54.804Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653577	Toolkit.Telemetry	DEBUG	TelemetryEnvironment::_onEnvironmentChange - calling TelemetrySession::onEnvironmentChange"
[task 2021-01-12T16:40:54.804Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653581	Toolkit.Telemetry	TRACE	TelemetrySession::_onEnvironmentChange: system-info"
[task 2021-01-12T16:40:54.804Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653589	Toolkit.Telemetry	TRACE	TelemetrySession::_onEnvironmentChange - throttling; last change was 0s ago."
[task 2021-01-12T16:40:54.804Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653593	Toolkit.Telemetry	TRACE	TelemetrySend::setup"
[task 2021-01-12T16:40:54.804Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653601	Toolkit.Telemetry	INFO	TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet."
[task 2021-01-12T16:40:54.804Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653607	Toolkit.Telemetry	TRACE	TelemetryStorage::_scanPendingPings"
[task 2021-01-12T16:40:54.805Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653613	Toolkit.Telemetry	TRACE	TelemetryStorage::_migrateAppDataPings"
[task 2021-01-12T16:40:54.805Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653615	Toolkit.Telemetry	TRACE	TelemetryStorage::_iterateAppDataPings"
[task 2021-01-12T16:40:54.805Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653621	Toolkit.Telemetry	TRACE	TelemetryStorage::_iterateAppDataPings - userApplicationDataDir is not defined. Is this a test?"
[task 2021-01-12T16:40:54.805Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653782	Toolkit.Telemetry	INFO	TelemetrySend::_checkPendingPings - pending ping count: 0"
[task 2021-01-12T16:40:54.805Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653791	Toolkit.Telemetry	TRACE	TelemetrySend::_checkPendingPings - no pending pings"
[task 2021-01-12T16:40:54.805Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653796	Toolkit.Telemetry	TRACE	TelemetryStorage::_enforcePendingPingsQuota"
[task 2021-01-12T16:40:54.805Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653805	Toolkit.Telemetry	TRACE	TelemetrySend::Scheduler::triggerSendingPings - active send task: false, immediately: true"
[task 2021-01-12T16:40:54.805Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653811	Toolkit.Telemetry	TRACE	TelemetrySend::Scheduler::_doSendTask iteration"
[task 2021-01-12T16:40:54.805Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653813	Toolkit.Telemetry	TRACE	TelemetrySend::Scheduler::_doSendTask - pending: 0, current: 0"
[task 2021-01-12T16:40:54.805Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653818	Toolkit.Telemetry	TRACE	TelemetrySend::Scheduler::_doSendTask - can send - pending: 0, current: 0"
[task 2021-01-12T16:40:54.806Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653821	Toolkit.Telemetry	TRACE	TelemetrySend::Scheduler::_doSendTask - no pending pings, bailing out"
[task 2021-01-12T16:40:54.806Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653825	Toolkit.Telemetry	TRACE	TelemetrySession::delayedInit"
[task 2021-01-12T16:40:54.806Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653827	Toolkit.Telemetry	TRACE	TelemetryStorage::_popAndPerformQueuedOperation - Performing queued operation."
[task 2021-01-12T16:40:54.806Z] 16:40:54     INFO -  "CONSOLE_MESSAGE: (info) 1610469653890	Toolkit.Telemetry	TRACE	TelemetryStorage::_popAndPerformQueuedOperation - Performing queued operation."
[task 2021-01-12T16:40:54.806Z] 16:40:54     INFO -  TEST-PASS | toolkit/components/telemetry/tests/unit/test_TelemetrySession.js | sessionTimeExcludingAndIncludingSuspend - [sessionTimeExcludingAndIncludingSuspend : 615] The session time including suspend should be positive - true == true
[task 2021-01-12T16:40:54.806Z] 16:40:54     INFO -  TEST-PASS | toolkit/components/telemetry/tests/unit/test_TelemetrySession.js | sessionTimeExcludingAndIncludingSuspend - [sessionTimeExcludingAndIncludingSuspend : 620] The session time excluding suspend should be positive - true == true
[task 2021-01-12T16:40:54.806Z] 16:40:54     INFO -  TEST-PASS | toolkit/components/telemetry/tests/unit/test_TelemetrySession.js | sessionTimeExcludingAndIncludingSuspend - [sessionTimeExcludingAndIncludingSuspend : 635] In test condition, the two uptimes should be close to each other - true == true
[task 2021-01-12T16:40:54.806Z] 16:40:54  WARNING -  TEST-UNEXPECTED-FAIL | toolkit/components/telemetry/tests/unit/test_TelemetrySession.js | sessionTimeExcludingAndIncludingSuspend - [sessionTimeExcludingAndIncludingSuspend : 649] The uptime with suspend must always been greater or equal to the uptime```

Comment 1

[Andreea Pavel [:apavel]]

There are 26 total failures in the last 7 days on mostly windows7-32 debug and opt
Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=326976258&repo=autoland&lineNumber=7660

[task 2021-01-18T00:00:40.533Z] 00:00:40 INFO - TEST-PASS | toolkit/components/reputationservice/test/unit/test_app_rep_windows.js | took 659ms
[task 2021-01-18T00:00:40.560Z] 00:00:40 INFO - TEST-START | toolkit/components/telemetry/tests/unit/test_TelemetrySession.js
[task 2021-01-18T00:00:41.756Z] 00:00:41 WARNING - TEST-UNEXPECTED-FAIL | toolkit/components/telemetry/tests/unit/test_TelemetrySession.js | xpcshell return code: 0
[task 2021-01-18T00:00:41.756Z] 00:00:41 INFO - TEST-INFO took 1193ms
[task 2021-01-18T00:00:41.757Z] 00:00:41 INFO - >>>>>>>
[task 2021-01-18T00:00:41.757Z] 00:00:41 INFO - PID 5624 | [Parent 5624, Main Thread] WARNING: Failed to get directory to cache.: file /builds/worker/checkouts/gecko/security/sandbox/win/src/sandboxbroker/sandboxBroker.cpp:119
[task 2021-01-18T00:00:41.757Z] 00:00:41 INFO - PID 5624 | [Parent 5624, Main Thread] WARNING: Failed to get directory to cache.: file /builds/worker/checkouts/gecko/security/sandbox/win/src/sandboxbroker/sandboxBroker.cpp:119
[task 2021-01-18T00:00:41.757Z] 00:00:41 INFO - PID 5624 | [Parent 5624, Main Thread] WARNING: Failed to get directory to cache.: file /builds/worker/checkouts/gecko/security/sandbox/win/src/sandboxbroker/sandboxBroker.cpp:119
[task 2021-01-18T00:00:41.758Z] 00:00:41 INFO - PID 5624 | [Parent 5624, Main Thread] WARNING: Failed to get directory to cache.: file /builds/worker/checkouts/gecko/security/sandbox/win/src/sandboxbroker/sandboxBroker.cpp:119
[task 2021-01-18T00:00:41.758Z] 00:00:41 INFO - PID 5624 | [Parent 5624, Main Thread] WARNING: Failed to get directory to cache.: file /builds/worker/checkouts/gecko/security/sandbox/win/src/sandboxbroker/sandboxBroker.cpp:119
[task 2021-01-18T00:00:41.759Z] 00:00:41 INFO - PID 5624 | [Parent 5624, Main Thread] WARNING: Couldn't get the user appdata directory. Crash events may not be produced.: file /builds/worker/checkouts/gecko/toolkit/crashreporter/nsExceptionHandler.cpp:2916
[task 2021-01-18T00:00:41.759Z] 00:00:41 INFO - (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2021-01-18T00:00:41.759Z] 00:00:41 INFO - (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2021-01-18T00:00:41.759Z] 00:00:41 INFO - (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2021-01-18T00:00:41.760Z] 00:00:41 INFO - running event loop
[task 2021-01-18T00:00:41.760Z] 00:00:41 INFO - toolkit/components/telemetry/tests/unit/test_TelemetrySession.js | Starting test_setup
[task 2021-01-18T00:00:41.760Z] 00:00:41 INFO - (xpcshell/head.js) | test test_setup pending (2)

Comment 2

[Intermittent Failures Robot]

31 failures in 3810 pushes (0.008 failures/push) were associated with this bug in the last 7 days.

This is the #28 most frequent failure this week.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **

Repository breakdown:

• autoland: 23
• mozilla-central: 3
• comm-central: 5

Platform breakdown:

• windows10-64: 2
• windows7-32: 21
• macosx1014-64-qr: 2
• windows7-32-shippable: 4
• linux1804-64: 1
• linux1804-64-tsan: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1686295&startday=2021-01-11&endday=2021-01-17&tree=all

Comment 3

[Paul Adenot (:padenot)]

Attachment: Bug 1686295 - Diagnosing patch. r?chutten

Two problems:

• Wrong Windows version (I meant to exclude all but Windows 10)
• Switch to the proper assertion so that the values are visible in the log in
  case of failure.

Comment 4

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/3f272a60d480
Diagnosing patch. r=chutten

Comment 5

[Narcis Beleuzu [:NarcisB]]

https://hg.mozilla.org/mozilla-central/rev/3f272a60d480

Comment 6

[Intermittent Failures Robot]

15 failures in 587 pushes (0.026 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 13
• comm-central: 1
• mozilla-central: 1

Platform breakdown:

• windows7-32: 11
• windows10-64: 1
• macosx1014-64-qr: 1
• windows7-32-shippable: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1686295&startday=2021-01-19&endday=2021-01-19&tree=all

Comment 7

[Atila Butkovits]

Still happening: https://treeherder.mozilla.org/logviewer?job_id=327226057&repo=autoland&lineNumber=2330

Paul, could you look into this?

Comment 8

[Intermittent Failures Robot]

16 failures in 720 pushes (0.022 failures/push) were associated with this bug yesterday.

Repository breakdown:

• mozilla-central: 2
• comm-central: 6
• autoland: 8

Platform and build breakdown:

• windows7-32-shippable: 3
  • opt: 3
• windows7-32: 12
  • opt: 7
  • debug: 5
• linux1804-64: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1686295&startday=2021-01-21&endday=2021-01-21&tree=all

Comment 9

[Intermittent Failures Robot]

64 failures in 3488 pushes (0.018 failures/push) were associated with this bug in the last 7 days.

This is the #17 most frequent failure this week.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **

Repository breakdown:

• comm-central: 14
• autoland: 38
• mozilla-central: 9
• try: 3

Platform and build breakdown:

• windows7-32: 50
  • debug: 24
  • opt: 26
• windows10-64: 1
  • debug: 1
• macosx1014-64-qr: 1
  • debug: 1
• windows7-32-shippable: 10
  • opt: 10
• linux1804-64-qr: 1
  • debug: 1
• linux1804-64: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1686295&startday=2021-01-18&endday=2021-01-24&tree=all

Comment 10

[Paul Adenot (:padenot)]

Attachment: Bug 1686295 - Compare AppConstants.platform to "win" on Windows to properly exclude some Windows < 10 from running a particular assertion. r?chutten

"linux" and "macosx" are spelt without abbreviation, but Windows is "win":
https://searchfox.org/mozilla-central/search?q=AppConstants.platform+%3D%3D+%22win%22&path=.

Comment 11

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/050d232035a7
Compare AppConstants.platform to "win" on Windows to properly exclude some Windows < 10 from running a particular assertion. r=chutten

Comment 12

[Andreea Pavel [:apavel]]

https://hg.mozilla.org/mozilla-central/rev/050d232035a7

Comment 13

[Sandor Molnar[:smolnar]]

This is still happening: https://treeherder.mozilla.org/logviewer?job_id=328060426&repo=autoland&lineNumber=5901

Paul, can you take a look at this?

Comment 14

[Natalia Csoregi [:nataliaCs]]

Update:

There have been 32 failures within the last 7 days:

• 6 failures on Linux 18.04 x64 debug
• 1 failure on Linux 18.04 x64 asan opt
• 6 failures on Linux 18.04 x64 WebRender debug / opt
• 1 failure on Windows 10 x64 debug
• 1 failure on Windows 7 Shippable opt
• 17 failures on Windows 7 opt / debug

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=328328837&repo=mozilla-central&lineNumber=3037

[task 2021-01-30T17:35:06.203Z] 17:35:06 INFO - Z:\task_1612026691\build\tests\xpcshell\head.js:_execute_test:567
[task 2021-01-30T17:35:06.203Z] 17:35:06 INFO - -e:null:1
[task 2021-01-30T17:35:06.203Z] 17:35:06 INFO - exiting test
[task 2021-01-30T17:35:06.204Z] 17:35:06 INFO - Unexpected exception NS_ERROR_ABORT:
[task 2021-01-30T17:35:06.204Z] 17:35:06 INFO - _abort_failed_test@Z:\task_1612026691\build\tests\xpcshell\head.js:827:20
[task 2021-01-30T17:35:06.204Z] 17:35:06 INFO - do_report_result@Z:\task_1612026691\build\tests\xpcshell\head.js:928:5
[task 2021-01-30T17:35:06.204Z] 17:35:06 INFO - Assert<@Z:\task_1612026691\build\tests\xpcshell\head.js:73:21
[task 2021-01-30T17:35:06.204Z] 17:35:06 INFO - proto.report@resource://testing-common/Assert.jsm:233:10
[task 2021-01-30T17:35:06.204Z] 17:35:06 INFO - compareNumbers@resource://testing-common/Assert.jsm:527:10
[task 2021-01-30T17:35:06.204Z] 17:35:06 INFO - greaterOrEqual@resource://testing-common/Assert.jsm:567:18
[task 2021-01-30T17:35:06.204Z] 17:35:06 INFO - sessionTimeExcludingAndIncludingSuspend@Z:/task_1612026691/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/test_TelemetrySession.js:647:12
[task 2021-01-30T17:35:06.204Z] 17:35:06 INFO - _do_main@Z:\task_1612026691\build\tests\xpcshell\head.js:239:6
[task 2021-01-30T17:35:06.204Z] 17:35:06 INFO - _execute_test@Z:\task_1612026691\build\tests\xpcshell\head.js:567:5
[task 2021-01-30T17:35:06.204Z] 17:35:06 INFO - @-e:1:1

Comment 15

[Intermittent Failures Robot]

44 failures in 3891 pushes (0.011 failures/push) were associated with this bug in the last 7 days.

This is the #17 most frequent failure this week.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **

Repository breakdown:

• autoland: 25
• comm-central: 7
• try: 4
• mozilla-central: 6
• mozilla-beta: 2

Platform and build breakdown:

• windows7-32: 19
  • debug: 14
  • opt: 5
• windows7-32-shippable: 6
  • opt: 6
• linux1804-64: 8
  • debug: 8
• linux1804-64-qr: 7
  • debug: 5
  • opt: 2
• macosx1014-64-qr: 1
  • opt: 1
• windows10-64: 1
  • debug: 1
• linux1804-64-asan: 1
  • opt: 1
• windows10-64-ccov-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1686295&startday=2021-01-25&endday=2021-01-31&tree=all

Comment 16

[Paul Adenot (:padenot)]

We need to fuzz this a bit.

Comment 17

[Intermittent Failures Robot]

10 failures in 3966 pushes (0.003 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 3
• mozilla-beta: 4
• mozilla-central: 1
• comm-central: 1
• try: 1

Platform and build breakdown:

• macosx1014-64-qr: 1
  • debug: 1
• windows7-32-shippable: 4
  • opt: 4
• linux1804-64-qr: 2
  • debug: 2
• windows10-64: 1
  • debug: 1
• linux1804-64: 2
  • debug: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1686295&startday=2021-02-01&endday=2021-02-07&tree=all

Comment 18

[Intermittent Failures Robot]

8 failures in 4322 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-beta: 5
• try: 1
• autoland: 2

Platform and build breakdown:

• windows7-32-shippable: 6
  • opt: 6
• linux1804-64: 1
  • debug: 1
• linux1804-64-tsan: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1686295&startday=2021-02-08&endday=2021-02-14&tree=all

Comment 19

[Intermittent Failures Robot]

6 failures in 3737 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-release: 3
• try: 1
• autoland: 1
• mozilla-central: 1

Platform and build breakdown:

• windows7-32-shippable: 3
  • opt: 3
• linux1804-64: 2
  • debug: 2
• linux1804-64-tsan: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1686295&startday=2021-02-15&endday=2021-02-21&tree=all

Comment 20

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• linux1804-64: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1686295&startday=2021-02-22&endday=2021-02-28&tree=all

Comment 21

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 2
• mozilla-release: 1

Platform and build breakdown:

• macosx1014-64-qr: 1
  • debug: 1
• linux1804-64-tsan: 1
  • opt: 1
• windows7-32-shippable: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1686295&startday=2021-03-01&endday=2021-03-07&tree=all

Comment 22

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 5

Platform and build breakdown:

• linux1804-64-asan: 1
  • opt: 1
• macosx1014-64-qr: 2
  • debug: 1
  • opt: 1
• linux1804-64-qr: 2
  • debug: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1686295&startday=2021-03-08&endday=2021-03-14&tree=all

Comment 23

[Intermittent Failures Robot]

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

Repository breakdown:

• try: 2
• autoland: 4

Platform and build breakdown:

• linux1804-64-qr: 3
  • debug: 3
• macosx1014-64-qr: 1
  • debug: 1
• linux1804-64: 2
  • opt: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1686295&startday=2021-03-15&endday=2021-03-21&tree=all

Comment 24

[Paul Adenot (:padenot)]

Attachment: Bug 1686295 - Flip the order of two time measurement calls in telemetry to provide actual guarantees to callers. r=chutten

See the comment in the code for the rationale.

Comment 25

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/e8ae095cb03a
Flip the order of two time measurement calls in telemetry to provide actual guarantees to callers. r=chutten

Comment 26

[Andreea Pavel [:apavel]]

https://hg.mozilla.org/mozilla-central/rev/e8ae095cb03a