Closed Bug 1736814 Opened 1 month ago Closed 1 month ago

Intermittent toolkit/components/telemetry/tests/unit/test_TelemetrySend.js | test_pingSenderShutdownBatch - [test_pingSenderShutdownBatch : 810] "12fbc852-031f-47fe-b3f4-733fb397754c" == "4ba2112c-4eeb-4b13-b94c-b9a5294bf94d"

Categories

(Toolkit :: Telemetry, defect, P1)

defect

Tracking

()

RESOLVED FIXED
95 Branch
Tracking Status
firefox95 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: chutten)

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

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


[task 2021-10-20T11:03:11.622Z] 11:03:11     INFO -  TEST-START | toolkit/components/telemetry/tests/unit/test_TelemetrySend.js
[task 2021-10-20T11:03:45.057Z] 11:03:45  WARNING -  TEST-UNEXPECTED-FAIL | toolkit/components/telemetry/tests/unit/test_TelemetrySend.js | xpcshell return code: 0
[task 2021-10-20T11:03:45.059Z] 11:03:45     INFO -  TEST-INFO took 33434ms
[task 2021-10-20T11:03:45.060Z] 11:03:45     INFO -  >>>>>>>
[task 2021-10-20T11:03:45.060Z] 11:03:45     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2021-10-20T11:03:45.060Z] 11:03:45     INFO -  (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2021-10-20T11:03:45.060Z] 11:03:45     INFO -  (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2021-10-20T11:03:45.060Z] 11:03:45     INFO -  running event loop
[task 2021-10-20T11:03:45.060Z] 11:03:45     INFO -  toolkit/components/telemetry/tests/unit/test_TelemetrySend.js | Starting test_setup
[task 2021-10-20T11:03:45.060Z] 11:03:45     INFO -  (xpcshell/head.js) | test test_setup pending (2)
[task 2021-10-20T11:03:45.060Z] 11:03:45     INFO -  (xpcshell/head.js) | test run_next_test 0 finished (2)
[task 2021-10-20T11:03:45.060Z] 11:03:45     INFO -  "CONSOLE_MESSAGE: (info) 1634727791877	addons.manager	DEBUG	Application has been upgraded"
[task 2021-10-20T11:03:45.060Z] 11:03:45     INFO -  "CONSOLE_MESSAGE: (info) 1634727791877	addons.manager	DEBUG	Loaded provider scope for resource://gre/modules/addons/XPIProvider.jsm: ["XPIProvider", "XPIInternal"]"
[task 2021-10-20T11:03:45.060Z] 11:03:45     INFO -  "CONSOLE_MESSAGE: (info) 1634727791879	addons.manager	DEBUG	Loaded provider scope for resource://gre/modules/addons/GMPProvider.jsm"
[task 2021-10-20T11:03:45.060Z] 11:03:45     INFO -  "CONSOLE_MESSAGE: (info) 1634727791880	addons.manager	DEBUG	Starting provider: XPIProvider"
[task 2021-10-20T11:03:45.060Z] 11:03:45     INFO -  "CONSOLE_MESSAGE: (info) 1634727791880	addons.xpi	DEBUG	startup"
[task 2021-10-20T11:03:45.061Z] 11:03:45     INFO -  "CONSOLE_MESSAGE: (info) 1634727791880	addons.xpi	INFO	SystemAddonLocation directory is missing"
[task 2021-10-20T11:03:45.061Z] 11:03:45     INFO -  "CONSOLE_MESSAGE: (info) 1634727791888	addons.xpi	INFO	Removing all system add-on upgrades."
[task 2021-10-20T11:03:45.061Z] 11:03:45     INFO -  "CONSOLE_MESSAGE: (info) 1634727791888	addons.xpi	DEBUG	checkForChanges"
[task 2021-10-20T11:03:45.061Z] 11:03:45     INFO -  "CONSOLE_MESSAGE: (info) 1634727791888	addons.xpi	DEBUG	Loaded add-on state: ${}"
[task 2021-10-20T11:03:45.061Z] 11:03:45     INFO -  "CONSOLE_MESSAGE: (info) 1634727791889	addons.xpi	DEBUG	New add-on tel-system-xpi@tests.mozilla.org in app-system-defaults"
[task 2021-10-20T11:03:45.061Z] 11:03:45     INFO -  "CONSOLE_MESSAGE: (info) 1634727791890	addons.xpi	WARN	Can't get modified time of C:\\Users\\task_1634727163\\AppData\\Local\\Temp\\xpc-profile-_bznrvgt\\sysfeatures\\app0\\tel-system-xpi@tests.mozilla.org.xpi"
[task 2021-10-20T11:03:45.062Z] 11:03:45     INFO -  "CONSOLE_MESSAGE: (info) 1634727791890	addons.xpi	DEBUG	scanForChanges changed: true, state: {}"
[task 2021-10-20T11:03:45.062Z] 11:03:45     INFO -  "CONSOLE_MESSAGE: (info) 1634727791896	addons.xpi-utils	DEBUG	Synchronously loading the add-ons database"
[task 2021-10-20T11:03:45.063Z] 11:03:45     INFO -  "CONSOLE_MESSAGE: (info) 1634727791896	addons.xpi-utils	DEBUG	Starting async load of XPI database C:\\Users\\task_1634727163\\AppData\\Local\\Temp\\xpc-profile-_bznrvgt\\extensions.json"
[task 2021-10-20T11:03:45.063Z] 11:03:45     INFO -  "CONSOLE_MESSAGE: (info) 1634727791900	addons.xpi-utils	DEBUG	New add-on tel-system-xpi@tests.mozilla.org installed in app-system-defaults"
[task 2021-10-20T11:03:45.064Z] 11:03:45     INFO -  "CONSOLE_MESSAGE: (info) 1634727791902	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.jsm :: get :: line 225"  data: no] Stack trace: get()@resource://gre/modules/addons/XPIInstall.jsm:225
[task 2021-10-20T11:03:45.065Z] 11:03:45     INFO -  syncLoadManifest()@resource://gre/modules/addons/XPIInstall.jsm:753
[task 2021-10-20T11:03:45.065Z] 11:03:45     INFO -  addMetadata()@resource://gre/modules/addons/XPIDatabase.jsm:2864
[task 2021-10-20T11:03:45.066Z] 11:03:45     INFO -  processFileChanges()@resource://gre/modules/addons/XPIDatabase.jsm:3329
[task 2021-10-20T11:03:45.066Z] 11:03:45     INFO -  checkForChanges()@resource://gre/modules/addons/XPIProvider.jsm:3066
[task 2021-10-20T11:03:45.066Z] 11:03:45     INFO -  startup()@resource://gre/modules/addons/XPIProvider.jsm:2471
[task 2021-10-20T11:03:45.066Z] 11:03:45     INFO -  callProvider()@resource://gre/modules/AddonManager.jsm:224
[task 2021-10-20T11:03:45.067Z] 11:03:45     INFO -  _startProvider()@resource://gre/modules/AddonManager.jsm:584
[task 2021-10-20T11:03:45.067Z] 11:03:45     INFO -  startup()@resource://gre/modules/AddonManager.jsm:811
[task 2021-10-20T11:03:45.067Z] 11:03:45     INFO -  startup()@resource://gre/modules/AddonManager.jsm:3514
[task 2021-10-20T11:03:45.068Z] 11:03:45     INFO -  observe()@resource://gre/modules/addonManager.js:81
[task 2021-10-20T11:03:45.068Z] 11:03:45     INFO -  promiseStartupManager()@resource://testing-common/AddonTestUtils.jsm:889
[task 2021-10-20T11:03:45.068Z] 11:03:45     INFO -  loadAddonManager()@Z:/task_1634727163/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/head.js:295
[task 2021-10-20T11:03:45.069Z] 11:03:45     INFO -  _do_main()@Z:\\task_1634727163\\build\\tests\\xpcshell\\head.js:240
[task 2021-10-20T11:03:45.069Z] 11:03:45     INFO -  _execute_test()@Z:\\task_1634727163\\build\\tests\\xpcshell\\head.js:597
[task 2021-10-20T11:03:45.069Z] 11:03:45     INFO -  -e:1"
[task 2021-10-20T11:03:45.070Z] 11:03:45     INFO -  "CONSOLE_MESSAGE: (info) 1634727791903	addons.xpi-utils	WARN	Could not uninstall invalid item from locked install location"
[task 2021-10-20T11:03:45.070Z] 11:03:45     INFO -  "CONSOLE_MESSAGE: (info) 1634727791904	addons.xpi-utils	DEBUG	Updating add-on states"
[task 2021-10-20T11:03:45.070Z] 11:03:45     INFO -  "CONSOLE_MESSAGE: (info) 1634727791905	addons.xpi-utils	DEBUG	Synchronously loading the add-ons database"
[task 2021-10-20T11:03:45.071Z] 11:03:45     INFO -  "CONSOLE_MESSAGE: (info) 1634727791907	addons.manager	DEBUG	Registering shutdown blocker for XPIProvider"
[task 2021-10-20T11:03:45.071Z] 11:03:45     INFO -  "CONSOLE_MESSAGE: (info) 1634727791907	addons.manager	DEBUG	Provider finished startup: XPIProvider"
[task 2021-10-20T11:03:45.072Z] 11:03:45     INFO -  "CONSOLE_MESSAGE: (info) 1634727791907	addons.manager	DEBUG	Completed startup sequence"
[task 2021-10-20T11:03:45.072Z] 11:03:45     INFO -  "CONSOLE_MESSAGE: (info) 1634727791914	Toolkit.Telemetry	TRACE	TelemetryEnvironment::constructor"
[task 2021-10-20T11:03:45.072Z] 11:03:45     INFO -  "CONSOLE_MESSAGE: (info) 1634727791934	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_getGFXData - Only one display adapter detected."
[task 2021-10-20T11:03:45.073Z] 11:03:45     INFO -  "CONSOLE_MESSAGE: (info) 1634727791936	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_updateSearchEngine - ignoring early call"
[task 2021-10-20T11:03:45.073Z] 11:03:45     INFO -  "CONSOLE_MESSAGE: (info) 1634727791936	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_updateAddons"
[task 2021-10-20T11:03:45.074Z] 11:03:45     INFO -  "CONSOLE_MESSAGE: (error) [JavaScript Error: "readUpdateConfig: Unable to read app update configuration file. Exception: [Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIProperties.get]"  nsresult: "0x80004005 (NS_ERROR_FAILURE)"  location: "JS frame :: resource://gre/modules/FileUtils.jsm :: FileUtils_getDir :: line 63"  data: no]" {file: "resource://gre/modules/UpdateUtils.jsm" line: 853}]
[task 2021-10-20T11:03:45.074Z] 11:03:45     INFO -  readUpdateConfig@resource://gre/modules/UpdateUtils.jsm:853:10
[task 2021-10-20T11:03:45.075Z] 11:03:45     INFO -  _do_main@Z:\\task_1634727163\\build\\tests\\xpcshell\\head.js:240:6
[task 2021-10-20T11:03:45.075Z] 11:03:45     INFO -  _execute_test@Z:\\task_1634727163\\build\\tests\\xpcshell\\head.js:597:5
[task 2021-10-20T11:03:45.075Z] 11:03:45     INFO -  @-e:1:1
[task 2021-10-20T11:03:45.075Z] 11:03:45     INFO -  "
[task 2021-10-20T11:03:45.076Z] 11:03:45     INFO -  "CONSOLE_MESSAGE: (error) [JavaScript Error: "readUpdateConfig: Unable to read app update configuration file. Exception: [Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIProperties.get]"  nsresult: "0x80004005 (NS_ERROR_FAILURE)"  location: "JS frame :: resource://gre/modules/FileUtils.jsm :: FileUtils_getDir :: line 63"  data: no]" {file: "resource://gre/modules/UpdateUtils.jsm" line: 853}]
[task 2021-10-20T11:03:45.077Z] 11:03:45     INFO -  readUpdateConfig@resource://gre/modules/UpdateUtils.jsm:853:10
[task 2021-10-20T11:03:45.077Z] 11:03:45     INFO -  _do_main@Z:\\task_1634727163\\build\\tests\\xpcshell\\head.js:240:6
[task 2021-10-20T11:03:45.077Z] 11:03:45     INFO -  _execute_test@Z:\\task_1634727163\\build\\tests\\xpcshell\\head.js:597:5
[task 2021-10-20T11:03:45.077Z] 11:03:45     INFO -  @-e:1:1
[task 2021-10-20T11:03:45.078Z] 11:03:45     INFO -  "
[task 2021-10-20T11:03:45.078Z] 11:03:45     INFO -  "CONSOLE_MESSAGE: (info) 1634727791941	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_updateAddons: addons differ"
[task 2021-10-20T11:03:45.078Z] 11:03:45     INFO -  "CONSOLE_MESSAGE: (info) 1634727791949	addons.xpi-utils	DEBUG	XPI Database saved, setting schema version preference to 33"
[task 2021-10-20T11:03:45.079Z] 11:03:45     INFO -  (xpcshell/head.js) | test run_next_test 1 pending (2)
[task 2021-10-20T11:03:45.079Z] 11:03:45     INFO -  (xpcshell/head.js) | test test_setup finished (2)
[task 2021-10-20T11:03:45.079Z] 11:03:45     INFO -  "CONSOLE_MESSAGE: (info) 1634727791950	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_startWatchingPrefs - [object Map]"
[task 2021-10-20T11:03:45.080Z] 11:03:45     INFO -  "CONSOLE_MESSAGE: (info) 1634727791951	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_stopWatchingPrefs"
[task 2021-10-20T11:03:45.080Z] 11:03:45     INFO -  "CONSOLE_MESSAGE: (info) 1634727791951	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_updateSearchEngine - ignoring early call"
[task 2021-10-20T11:03:45.081Z] 11:03:45     INFO -  "CONSOLE_MESSAGE: (info) 1634727791951	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_startWatchingPrefs - [object Map]"
[task 2021-10-20T11:03:45.081Z] 11:03:45     INFO -  "CONSOLE_MESSAGE: (info) 1634727791951	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: nsPref:changed, aData: toolkit.telemetry.healthping.enabled"
[task 2021-10-20T11:03:45.081Z] 11:03:45     INFO -  toolkit/components/telemetry/tests/unit/test_TelemetrySend.js | Starting test_sendPendingPings
[task 2021-10-20T11:03:45.082Z] 11:03:45     INFO -  (xpcshell/head.js) | test test_sendPendingPings pending (2)
[task 2021-10-20T11:03:45.082Z] 11:03:45     INFO -  (xpcshell/head.js) | test run_next_test 1 finished (2)
[task 2021-10-20T11:03:45.083Z] 11:03:45     INFO -  "CONSOLE_MESSAGE: (info) 1634727791955	Toolkit.Telemetry	TRACE	TelemetryController::submitExternalPing - type: test-sendPendingPings-A, aOptions: {"addClientId":false,"addEnvironment":false,"usePingSender":false}"
<...>
[task 2021-10-20T11:03:45.186Z] 11:03:45     INFO -  "CONSOLE_MESSAGE: (info) 1634727792230	Toolkit.Telemetry	TRACE	TelemetrySend::submitPing - can't send ping now, persisting to disk - canSendNow: false"
[task 2021-10-20T11:03:45.186Z] 11:03:45     INFO -  "CONSOLE_MESSAGE: (info) 1634727792232	Toolkit.Telemetry	TRACE	TelemetryStorage::savePingToFile - path: C:\\Users\\task_1634727163\\AppData\\Local\\Temp\\xpc-profile-_bznrvgt\\datareporting\\archived\\2021-10\\1634724000000.93bd0011-2c8f-4e1c-bee0-a00000000019.test-sendPendingPings-A.jsonlz4"
[task 2021-10-20T11:03:45.187Z] 11:03:45     INFO -  "CONSOLE_MESSAGE: (info) 1634727792233	Toolkit.Telemetry	TRACE	TelemetryStorage::savePingToFile - path: C:\\Users\\task_1634727163\\AppData\\Local\\Temp\\xpc-profile-_bznrvgt\\saved-telemetry-pings\\93bd0011-2c8f-4e1c-bee0-a00000000019"
[task 2021-10-20T11:03:45.187Z] 11:03:45     INFO -  "CONSOLE_MESSAGE: (info) 1634727792241	Toolkit.Telemetry	TRACE	TelemetryStorage::savePendingPing - saved ping with id 93bd0011-2c8f-4e1c-bee0-a00000000019"
[task 2021-10-20T11:03:45.188Z] 11:03:45     INFO -  TEST-PASS | toolkit/components/telemetry/tests/unit/test_TelemetrySend.js | test_sendPendingPings - [test_sendPendingPings : 170] Should have correct pending ping count - 20 == 20

Looks analogous to bug 1736179: pings submitted in one order are being uploaded in a different one. I'll relax the ordering requirement in the test.

Assignee: nobody → chutten
Status: NEW → ASSIGNED
Priority: P5 → P1

Also, appease eslint while we're here.

Pushed by chutten@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/88eee08dbd29
Allow pingsender-sent pings to be sent out of order r=TravisLong
Status: ASSIGNED → RESOLVED
Closed: 1 month ago
Resolution: --- → FIXED
Target Milestone: --- → 95 Branch
You need to log in before you can comment on or make changes to this bug.