Closed
Bug 1736814
Opened 3 years ago
Closed 3 years 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)
Toolkit
Telemetry
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
|
Assignee | |
Comment 1•3 years ago
|
||
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
|
|
Assignee | |
Comment 2•3 years ago
|
||
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
|
||
Comment 4•3 years ago
|
||
| bugherder | ||
Status: ASSIGNED → RESOLVED
Closed: 3 years ago
status-firefox95:
--- → fixed
Resolution: --- → FIXED
Target Milestone: --- → 95 Branch
| Comment hidden (Intermittent Failures Robot) |
You need to log in
before you can comment on or make changes to this bug.
Description
•