Open Bug 1807929 Opened 1 year ago Updated 1 year ago

some toolkit/components/telemetry/tests/unit/ tests fail against MSIX builds

Categories

(Toolkit :: Telemetry, defect, P4)

Product:
Toolkit
Component:
Telemetry
Type:
defect

Tracking

()

People

(Reporter: bhearsum, Unassigned)

References

Details

The logs are too large to fully attach here, but can be viewed on this treeherder job.

The relevant snippets, I believe, are:

[task 2022-12-28T20:30:25.025Z] 20:30:25     INFO -  "CONSOLE_MESSAGE: (error) [JavaScript Error: "NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIPropertyBag.getProperty]" {file: "resource://testing-common/TelemetryEnvironmentTesting.jsm" line: 75}]
[task 2022-12-28T20:30:25.025Z] 20:30:25     INFO -  getProperty@resource://testing-common/TelemetryEnvironmentTesting.jsm:75:60
[task 2022-12-28T20:30:25.026Z] 20:30:25     INFO -  getSysinfoProperty@resource://gre/modules/TelemetryEnvironment.jsm:510:29
[task 2022-12-28T20:30:25.026Z] 20:30:25     INFO -  _getSystem@resource://gre/modules/TelemetryEnvironment.jsm:2076:21
[task 2022-12-28T20:30:25.026Z] 20:30:25     INFO -  EnvironmentCache@resource://gre/modules/TelemetryEnvironment.jsm:980:18
[task 2022-12-28T20:30:25.026Z] 20:30:25     INFO -  getGlobal@resource://gre/modules/TelemetryEnvironment.jsm:97:26
[task 2022-12-28T20:30:25.026Z] 20:30:25     INFO -  delayedInit@resource://gre/modules/TelemetryEnvironment.jsm:112:12
[task 2022-12-28T20:30:25.027Z] 20:30:25     INFO -  setup@Z:/task_167225684093308/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/test_TelemetryEnvironment_search.js:75:30
[task 2022-12-28T20:30:25.027Z] 20:30:25     INFO -  _do_main@Z:\\task_167225684093308\\build\\tests\\xpcshell\\head.js:238:6
[task 2022-12-28T20:30:25.027Z] 20:30:25     INFO -  _execute_test@Z:\\task_167225684093308\\build\\tests\\xpcshell\\head.js:585:5
[task 2022-12-28T20:30:25.027Z] 20:30:25     INFO -  @-e:1:1
[task 2022-12-28T20:30:25.027Z] 20:30:25     INFO -  "

[task 2022-12-28T20:30:25.053Z] 20:30:25  WARNING -  TEST-UNEXPECTED-FAIL | toolkit/components/telemetry/tests/unit/test_TelemetryEnvironment_search.js | setup - [setup : 347] "undefined" == "object"
[task 2022-12-28T20:30:25.054Z] 20:30:25     INFO -  resource://testing-common/TelemetryEnvironmentTesting.jsm:checkSettingsSection:347
[task 2022-12-28T20:30:25.054Z] 20:30:25     INFO -  resource://testing-common/TelemetryEnvironmentTesting.jsm:checkEnvironmentData:863
[task 2022-12-28T20:30:25.054Z] 20:30:25     INFO -  Z:/task_167225684093308/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/test_TelemetryEnvironment_search.js:setup:86
[task 2022-12-28T20:30:25.054Z] 20:30:25     INFO -  Z:\task_167225684093308\build\tests\xpcshell\head.js:_do_main:238
[task 2022-12-28T20:30:25.054Z] 20:30:25     INFO -  Z:\task_167225684093308\build\tests\xpcshell\head.js:_execute_test:585
[task 2022-12-28T20:30:25.055Z] 20:30:25     INFO -  -e:null:1
[task 2022-12-28T20:30:25.055Z] 20:30:25     INFO -  exiting test
[task 2022-12-28T20:30:25.055Z] 20:30:25     INFO -  Unexpected exception NS_ERROR_ABORT:
[task 2022-12-28T20:30:25.056Z] 20:30:25     INFO -  _abort_failed_test@Z:\task_167225684093308\build\tests\xpcshell\head.js:863:20
[task 2022-12-28T20:30:25.056Z] 20:30:25     INFO -  do_report_result@Z:\task_167225684093308\build\tests\xpcshell\head.js:964:5
[task 2022-12-28T20:30:25.056Z] 20:30:25     INFO -  Assert<@Z:\task_167225684093308\build\tests\xpcshell\head.js:71:21
[task 2022-12-28T20:30:25.056Z] 20:30:25     INFO -  Assert.prototype.report@resource://testing-common/Assert.sys.mjs:240:10
[task 2022-12-28T20:30:25.057Z] 20:30:25     INFO -  equal@resource://testing-common/Assert.sys.mjs:282:8
[task 2022-12-28T20:30:25.057Z] 20:30:25     INFO -  checkSettingsSection@resource://testing-common/TelemetryEnvironmentTesting.jsm:347:19
[task 2022-12-28T20:30:25.057Z] 20:30:25     INFO -  checkEnvironmentData@resource://testing-common/TelemetryEnvironmentTesting.jsm:863:10
[task 2022-12-28T20:30:25.057Z] 20:30:25     INFO -  setup@Z:/task_167225684093308/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/test_TelemetryEnvironment_search.js:86:31
[task 2022-12-28T20:30:25.057Z] 20:30:25     INFO -  _do_main@Z:\task_167225684093308\build\tests\xpcshell\head.js:238:6
[task 2022-12-28T20:30:25.058Z] 20:30:25     INFO -  _execute_test@Z:\task_167225684093308\build\tests\xpcshell\head.js:585:5
[task 2022-12-28T20:30:25.058Z] 20:30:25     INFO -  @-e:1:1
[task 2022-12-28T20:30:25.058Z] 20:30:25     INFO -  exiting test

There are references here to attribution code failing, so this might be fixed by bug 1807924 - but I'm honestly not sure.

Also noticed some other tests in the same directory failing:

[task 2022-12-28T20:30:49.278Z] 20:30:49  WARNING -  TEST-UNEXPECTED-FAIL | toolkit/components/telemetry/tests/unit/test_TelemetryScalars_buildFaster.js | xpcshell return code: 0
[task 2022-12-28T20:30:49.279Z] 20:30:49     INFO -  TEST-INFO took 168ms
[task 2022-12-28T20:30:49.279Z] 20:30:49     INFO -  >>>>>>>
[task 2022-12-28T20:30:49.280Z] 20:30:49     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2022-12-28T20:30:49.280Z] 20:30:49     INFO -  (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2022-12-28T20:30:49.280Z] 20:30:49     INFO -  (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2022-12-28T20:30:49.280Z] 20:30:49     INFO -  running event loop
[task 2022-12-28T20:30:49.280Z] 20:30:49     INFO -  toolkit/components/telemetry/tests/unit/test_TelemetryScalars_buildFaster.js | Starting test_setup
[task 2022-12-28T20:30:49.281Z] 20:30:49     INFO -  (xpcshell/head.js) | test test_setup pending (2)
[task 2022-12-28T20:30:49.281Z] 20:30:49     INFO -  (xpcshell/head.js) | test run_next_test 0 finished (2)
[task 2022-12-28T20:30:49.281Z] 20:30:49     INFO -  (xpcshell/head.js) | test run_next_test 1 pending (2)
[task 2022-12-28T20:30:49.282Z] 20:30:49     INFO -  (xpcshell/head.js) | test test_setup finished (2)
[task 2022-12-28T20:30:49.282Z] 20:30:49     INFO -  toolkit/components/telemetry/tests/unit/test_TelemetryScalars_buildFaster.js | Starting test_invalidJSON
[task 2022-12-28T20:30:49.282Z] 20:30:49     INFO -  (xpcshell/head.js) | test test_invalidJSON pending (2)
[task 2022-12-28T20:30:49.282Z] 20:30:49     INFO -  (xpcshell/head.js) | test run_next_test 1 finished (2)
[task 2022-12-28T20:30:49.282Z] 20:30:49     INFO -  Unexpected exception Error:
[task 2022-12-28T20:30:49.283Z] 20:30:49     INFO -  exiting test

[task 2022-12-28T20:30:52.085Z] 20:30:52  WARNING -  TEST-UNEXPECTED-FAIL | toolkit/components/telemetry/tests/unit/test_TelemetryEvents_buildFaster.js | xpcshell return code: 0
[task 2022-12-28T20:30:52.095Z] 20:30:52     INFO -  TEST-INFO took 160ms
[task 2022-12-28T20:30:52.095Z] 20:30:52     INFO -  >>>>>>>
[task 2022-12-28T20:30:52.096Z] 20:30:52     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2022-12-28T20:30:52.096Z] 20:30:52     INFO -  (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2022-12-28T20:30:52.096Z] 20:30:52     INFO -  (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2022-12-28T20:30:52.096Z] 20:30:52     INFO -  running event loop
[task 2022-12-28T20:30:52.096Z] 20:30:52     INFO -  toolkit/components/telemetry/tests/unit/test_TelemetryEvents_buildFaster.js | Starting test_setup
[task 2022-12-28T20:30:52.097Z] 20:30:52     INFO -  (xpcshell/head.js) | test test_setup pending (2)
[task 2022-12-28T20:30:52.097Z] 20:30:52     INFO -  (xpcshell/head.js) | test run_next_test 0 finished (2)
[task 2022-12-28T20:30:52.097Z] 20:30:52     INFO -  (xpcshell/head.js) | test run_next_test 1 pending (2)
[task 2022-12-28T20:30:52.097Z] 20:30:52     INFO -  (xpcshell/head.js) | test test_setup finished (2)
[task 2022-12-28T20:30:52.097Z] 20:30:52     INFO -  toolkit/components/telemetry/tests/unit/test_TelemetryEvents_buildFaster.js | Starting test_invalidJSON
[task 2022-12-28T20:30:52.097Z] 20:30:52     INFO -  (xpcshell/head.js) | test test_invalidJSON pending (2)
[task 2022-12-28T20:30:52.098Z] 20:30:52     INFO -  (xpcshell/head.js) | test run_next_test 1 finished (2)
[task 2022-12-28T20:30:52.098Z] 20:30:52     INFO -  Unexpected exception Error:
[task 2022-12-28T20:30:52.098Z] 20:30:52     INFO -  exiting test

[task 2022-12-28T20:31:00.319Z] 20:31:00  WARNING -  TEST-UNEXPECTED-FAIL | toolkit/components/telemetry/tests/unit/test_ThirdPartyModulesPing.js | xpcshell return code: 0
[task 2022-12-28T20:31:00.322Z] 20:31:00     INFO -  TEST-INFO took 842ms
[task 2022-12-28T20:31:00.322Z] 20:31:00     INFO -  >>>>>>>
[task 2022-12-28T20:31:00.323Z] 20:31:00     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2022-12-28T20:31:00.323Z] 20:31:00     INFO -  (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2022-12-28T20:31:00.323Z] 20:31:00     INFO -  (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2022-12-28T20:31:00.323Z] 20:31:00     INFO -  running event loop
[task 2022-12-28T20:31:00.324Z] 20:31:00     INFO -  toolkit/components/telemetry/tests/unit/test_ThirdPartyModulesPing.js | Starting setup
[task 2022-12-28T20:31:00.324Z] 20:31:00     INFO -  (xpcshell/head.js) | test setup pending (2)
[task 2022-12-28T20:31:00.324Z] 20:31:00     INFO -  (xpcshell/head.js) | test run_next_test 0 finished (2)
[task 2022-12-28T20:31:00.324Z] 20:31:00     INFO -  "CONSOLE_MESSAGE: (info) 1672259459694	Toolkit.Telemetry	TRACE	TelemetryController::setupTelemetry"
[task 2022-12-28T20:31:00.325Z] 20:31:00     INFO -  "CONSOLE_MESSAGE: (info) 1672259459694	Toolkit.Telemetry	TRACE	TelemetryController::registerJsProbes - registering builtin JS probes"
[task 2022-12-28T20:31:00.325Z] 20:31:00     INFO -  "CONSOLE_MESSAGE: (info) 1672259459694	Toolkit.Telemetry	TRACE	TelemetryController::registerScalarProbes - registering scalar builtin JS probes"
[task 2022-12-28T20:31:00.326Z] 20:31:00     INFO -  "CONSOLE_MESSAGE: (info) 1672259459694	Toolkit.Telemetry	TRACE	TelemetryController::loadProbeDefinitions - no builtin JS probe file ScalarArtifactDefinitions.json"
[task 2022-12-28T20:31:00.326Z] 20:31:00     INFO -  "CONSOLE_MESSAGE: (info) 1672259459696	Toolkit.Telemetry	TRACE	TelemetryReportingPolicy::setup"
[task 2022-12-28T20:31:00.326Z] 20:31:00     INFO -  "CONSOLE_MESSAGE: (info) 1672259459696	Toolkit.Telemetry	CONFIG	TelemetryController::enableTelemetryRecording - canRecordBase:true, canRecordExtended: true"
[task 2022-12-28T20:31:00.326Z] 20:31:00     INFO -  "CONSOLE_MESSAGE: (info) 1672259459696	Toolkit.Telemetry	TRACE	TelemetrySession::earlyInit"
[task 2022-12-28T20:31:00.327Z] 20:31:00     INFO -  "CONSOLE_MESSAGE: (info) 1672259459696	Toolkit.Telemetry	INFO	TelemetryReportingPolicy::get dataSubmissionPolicyNotifiedDate - No date stored yet."
[task 2022-12-28T20:31:00.327Z] 20:31:00     INFO -  "CONSOLE_MESSAGE: (info) 1672259459696	Toolkit.Telemetry	TRACE	UpdatePing::init - enabled: true"
[task 2022-12-28T20:31:00.328Z] 20:31:00     INFO -  "CONSOLE_MESSAGE: (info) 1672259459697	Toolkit.Telemetry	TRACE	TelemetryController::registerEventProbes - registering builtin JS Event probes"
[task 2022-12-28T20:31:00.328Z] 20:31:00     INFO -  "CONSOLE_MESSAGE: (info) 1672259459697	Toolkit.Telemetry	TRACE	TelemetryController::loadProbeDefinitions - no builtin JS probe file EventArtifactDefinitions.json"
[task 2022-12-28T20:31:00.328Z] 20:31:00     INFO -  "CONSOLE_MESSAGE: (info) 1672259459716	Toolkit.Telemetry	TRACE	TelemetryEnvironment::constructor"
[task 2022-12-28T20:31:00.329Z] 20:31:00     INFO -  "CONSOLE_MESSAGE: (info) 1672259459745	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_getGFXData - Only one display adapter detected."
[task 2022-12-28T20:31:00.329Z] 20:31:00     INFO -  "CONSOLE_MESSAGE: (info) 1672259459750	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_updateSearchEngine - ignoring early call"
[task 2022-12-28T20:31:00.330Z] 20:31:00     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/UpdateUtils.sys.mjs :: getConfigFilePath :: line 150"  data: no]" {file: "resource://gre/modules/UpdateUtils.sys.mjs" line: 861}]
[task 2022-12-28T20:31:00.331Z] 20:31:00     INFO -  readUpdateConfig@resource://gre/modules/UpdateUtils.sys.mjs:861:10
[task 2022-12-28T20:31:00.331Z] 20:31:00     INFO -  _do_main@Z:\\task_167225684093308\\build\\tests\\xpcshell\\head.js:238:6
[task 2022-12-28T20:31:00.331Z] 20:31:00     INFO -  _execute_test@Z:\\task_167225684093308\\build\\tests\\xpcshell\\head.js:585:5
[task 2022-12-28T20:31:00.331Z] 20:31:00     INFO -  @-e:1:1
[task 2022-12-28T20:31:00.331Z] 20:31:00     INFO -  "

[task 2022-12-28T20:31:00.400Z] 20:31:00  WARNING -  TEST-UNEXPECTED-FAIL | toolkit/components/telemetry/tests/unit/test_ThirdPartyModulesPing.js | test_send_ping - [test_send_ping : 158] Trustworthiness == expected for module: modules-test.dll - true == false
[task 2022-12-28T20:31:00.401Z] 20:31:00     INFO -  Z:/task_167225684093308/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/test_ThirdPartyModulesPing.js:test_send_ping:158
[task 2022-12-28T20:31:00.401Z] 20:31:00     INFO -  Z:\task_167225684093308\build\tests\xpcshell\head.js:_do_main:238
[task 2022-12-28T20:31:00.401Z] 20:31:00     INFO -  Z:\task_167225684093308\build\tests\xpcshell\head.js:_execute_test:585
[task 2022-12-28T20:31:00.401Z] 20:31:00     INFO -  -e:null:1
[task 2022-12-28T20:31:00.401Z] 20:31:00     INFO -  exiting test
[task 2022-12-28T20:31:00.401Z] 20:31:00     INFO -  Unexpected exception NS_ERROR_ABORT:
[task 2022-12-28T20:31:00.402Z] 20:31:00     INFO -  _abort_failed_test@Z:\task_167225684093308\build\tests\xpcshell\head.js:863:20
[task 2022-12-28T20:31:00.402Z] 20:31:00     INFO -  do_report_result@Z:\task_167225684093308\build\tests\xpcshell\head.js:964:5
[task 2022-12-28T20:31:00.402Z] 20:31:00     INFO -  Assert<@Z:\task_167225684093308\build\tests\xpcshell\head.js:71:21
[task 2022-12-28T20:31:00.403Z] 20:31:00     INFO -  Assert.prototype.report@resource://testing-common/Assert.sys.mjs:240:10
[task 2022-12-28T20:31:00.403Z] 20:31:00     INFO -  equal@resource://testing-common/Assert.sys.mjs:282:8
[task 2022-12-28T20:31:00.403Z] 20:31:00     INFO -  test_send_ping@Z:/task_167225684093308/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/test_ThirdPartyModulesPing.js:158:12
[task 2022-12-28T20:31:00.403Z] 20:31:00     INFO -  _do_main@Z:\task_167225684093308\build\tests\xpcshell\head.js:238:6
[task 2022-12-28T20:31:00.403Z] 20:31:00     INFO -  _execute_test@Z:\task_167225684093308\build\tests\xpcshell\head.js:585:5
[task 2022-12-28T20:31:00.404Z] 20:31:00     INFO -  @-e:1:1
[task 2022-12-28T20:31:00.404Z] 20:31:00     INFO -  exiting test

[task 2022-12-28T20:35:08.151Z] 20:35:08  WARNING -  TEST-UNEXPECTED-FAIL | toolkit/components/telemetry/tests/unit/test_TelemetryEnvironment.js | test_checkEnvironment - [test_checkEnvironment : 347] "undefined" == "object"
[task 2022-12-28T20:35:08.151Z] 20:35:08     INFO -  resource://testing-common/TelemetryEnvironmentTesting.jsm:checkSettingsSection:347
[task 2022-12-28T20:35:08.151Z] 20:35:08     INFO -  resource://testing-common/TelemetryEnvironmentTesting.jsm:checkEnvironmentData:863
[task 2022-12-28T20:35:08.151Z] 20:35:08     INFO -  Z:/task_167225684093308/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/test_TelemetryEnvironment.js:test_checkEnvironment:219
[task 2022-12-28T20:35:08.151Z] 20:35:08     INFO -  Z:\task_167225684093308\build\tests\xpcshell\head.js:_do_main:238
[task 2022-12-28T20:35:08.152Z] 20:35:08     INFO -  Z:\task_167225684093308\build\tests\xpcshell\head.js:_execute_test:585
[task 2022-12-28T20:35:08.152Z] 20:35:08     INFO -  -e:null:1
[task 2022-12-28T20:35:08.152Z] 20:35:08     INFO -  exiting test
[task 2022-12-28T20:35:08.152Z] 20:35:08     INFO -  Unexpected exception NS_ERROR_ABORT:
[task 2022-12-28T20:35:08.153Z] 20:35:08     INFO -  _abort_failed_test@Z:\task_167225684093308\build\tests\xpcshell\head.js:863:20
[task 2022-12-28T20:35:08.153Z] 20:35:08     INFO -  do_report_result@Z:\task_167225684093308\build\tests\xpcshell\head.js:964:5
[task 2022-12-28T20:35:08.153Z] 20:35:08     INFO -  Assert<@Z:\task_167225684093308\build\tests\xpcshell\head.js:71:21
[task 2022-12-28T20:35:08.153Z] 20:35:08     INFO -  Assert.prototype.report@resource://testing-common/Assert.sys.mjs:240:10
[task 2022-12-28T20:35:08.153Z] 20:35:08     INFO -  equal@resource://testing-common/Assert.sys.mjs:282:8
[task 2022-12-28T20:35:08.154Z] 20:35:08     INFO -  checkSettingsSection@resource://testing-common/TelemetryEnvironmentTesting.jsm:347:19
[task 2022-12-28T20:35:08.154Z] 20:35:08     INFO -  checkEnvironmentData@resource://testing-common/TelemetryEnvironmentTesting.jsm:863:10
[task 2022-12-28T20:35:08.154Z] 20:35:08     INFO -  test_checkEnvironment@Z:/task_167225684093308/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/test_TelemetryEnvironment.js:219:31
[task 2022-12-28T20:35:08.154Z] 20:35:08     INFO -  _do_main@Z:\task_167225684093308\build\tests\xpcshell\head.js:238:6
[task 2022-12-28T20:35:08.154Z] 20:35:08     INFO -  _execute_test@Z:\task_167225684093308\build\tests\xpcshell\head.js:585:5
[task 2022-12-28T20:35:08.154Z] 20:35:08     INFO -  @-e:1:1
[task 2022-12-28T20:35:08.155Z] 20:35:08     INFO -  exiting test
Summary: toolkit/components/telemetry/tests/unit/test_TelemetryEnvironment_search.js fails against MSIX builds → some toolkit/components/telemetry/tests/unit/ tests fail against MSIX builds

Was Telemetry from MSIX builds verified to be correct? This could be a sign that we can't trust the data.

Flags: needinfo?(bhearsum)

(In reply to Chris H-C :chutten from comment #2)

Was Telemetry from MSIX builds verified to be correct? This could be a sign that we can't trust the data.

I believe QA did testing around this before we first shipped it -- but that was about a year ago now, so perhaps that's not much of a sign at this point.

We are certainly getting data from MSIX builds (eg: https://sql.telemetry.mozilla.org/queries/89655/source#221953 shows new installs coming in at comparable-ish levels to the data we get from Microsoft. Our data shows fewer "installs" than Microsoft's, but this ping is sent at first run...so that's to be expected at some level.) - so that's at least a sign that it's not horribly broken. But that doesn't mean it's not broken in some circumstances.

Flags: needinfo?(bhearsum)

The severity field is not set for this bug.
:chutten, could you have a look please?

For more information, please visit auto_nag documentation.

Flags: needinfo?(chutten)

This bug is about unskipiffing the tests skipped in bug 1805919.

Severity: -- → S4
Flags: needinfo?(chutten)
Priority: -- → P4
See Also: → 1805919
You need to log in before you can comment on or make changes to this bug.