Closed Bug 1885310 Opened 7 months ago Closed 3 months ago

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

Categories

(Toolkit :: Telemetry, defect, P1)

defect

Tracking

()

RESOLVED FIXED
130 Branch
Tracking Status
firefox-esr115 --- unaffected
firefox-esr128 --- fixed
firefox127 --- wontfix
firefox128 --- wontfix
firefox129 --- fixed
firefox130 --- fixed

People

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

References

(Regression)

Details

(Keywords: intermittent-failure, intermittent-testcase, regression, Whiteboard: [stockwell disable-recommended])

Attachments

(1 file)

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


TEST-PASS | toolkit/components/telemetry/tests/unit/test_TelemetryEnvironment.js | test_environmentDidntChange - [test_environmentDidntChange : 827] "number" == "number"
[task 2024-03-14T11:53:44.416Z] 11:53:44     INFO -  (xpcshell/head.js) | test run_next_test 24 pending (2)
[task 2024-03-14T11:53:44.416Z] 11:53:44     INFO -  (xpcshell/head.js) | test test_environmentDidntChange finished (2)
[task 2024-03-14T11:53:44.416Z] 11:53:44     INFO -  "CONSOLE_MESSAGE: (info) 1710417222136	Toolkit.Telemetry	TRACE	TelemetryEnvironment::shutdown"
[task 2024-03-14T11:53:44.417Z] 11:53:44     INFO -  "CONSOLE_MESSAGE: (info) 1710417222136	Toolkit.Telemetry	TRACE	TelemetryEnvironment::constructor"
[task 2024-03-14T11:53:44.417Z] 11:53:44     INFO -  "CONSOLE_MESSAGE: (info) 1710417222137	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_getGFXData - Only one display adapter detected."
[task 2024-03-14T11:53:44.417Z] 11:53:44     INFO -  "CONSOLE_MESSAGE: (error) [JavaScript Error: "NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIPropertyBag.getProperty]" {file: "resource://testing-common/TelemetryEnvironmentTesting.sys.mjs" line: 65}]
[task 2024-03-14T11:53:44.418Z] 11:53:44     INFO -  getProperty@resource://testing-common/TelemetryEnvironmentTesting.sys.mjs:65:60
[task 2024-03-14T11:53:44.418Z] 11:53:44     INFO -  getSysinfoProperty@resource://gre/modules/TelemetryEnvironment.sys.mjs:490:29
[task 2024-03-14T11:53:44.418Z] 11:53:44     INFO -  _getSystem@resource://gre/modules/TelemetryEnvironment.sys.mjs:2082:21
[task 2024-03-14T11:53:44.418Z] 11:53:44     INFO -  EnvironmentCache@resource://gre/modules/TelemetryEnvironment.sys.mjs:977:18
[task 2024-03-14T11:53:44.419Z] 11:53:44     INFO -  getGlobal@resource://gre/modules/TelemetryEnvironment.sys.mjs:77:26
[task 2024-03-14T11:53:44.419Z] 11:53:44     INFO -  testCleanRestart@resource://gre/modules/TelemetryEnvironment.sys.mjs:201:12
[task 2024-03-14T11:53:44.420Z] 11:53:44     INFO -  test_environmentDidntChange@Z:/task_171041633923738/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/test_TelemetryEnvironment.js:1455:30
[task 2024-03-14T11:53:44.420Z] 11:53:44     INFO -  _run_next_test/<@Z:\\task_171041633923738\\build\\tests\\xpcshell\\head.js:1762:22
[task 2024-03-14T11:53:44.420Z] 11:53:44     INFO -  _run_next_test@Z:\\task_171041633923738\\build\\tests\\xpcshell\\head.js:1762:38
[task 2024-03-14T11:53:44.420Z] 11:53:44     INFO -  run@Z:\\task_171041633923738\\build\\tests\\xpcshell\\head.js:808:9
[task 2024-03-14T11:53:44.420Z] 11:53:44     INFO -  _do_main@Z:\\task_171041633923738\\build\\tests\\xpcshell\\head.js:245:6
[task 2024-03-14T11:53:44.421Z] 11:53:44     INFO -  _execute_test@Z:\\task_171041633923738\\build\\tests\\xpcshell\\head.js:596:5
[task 2024-03-14T11:53:44.421Z] 11:53:44     INFO -  @-e:1:1
[task 2024-03-14T11:53:44.421Z] 11:53:44     INFO -  "
[task 2024-03-14T11:53:44.422Z] 11:53:44     INFO -  "CONSOLE_MESSAGE: (error) [JavaScript Error: "NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIPropertyBag.getProperty]" {file: "resource://testing-common/TelemetryEnvironmentTesting.sys.mjs" line: 65}]
[task 2024-03-14T11:53:44.422Z] 11:53:44     INFO -  getProperty@resource://testing-common/TelemetryEnvironmentTesting.sys.mjs:65:60
[task 2024-03-14T11:53:44.422Z] 11:53:44     INFO -  getSysinfoProperty@resource://gre/modules/TelemetryEnvironment.sys.mjs:490:29
[task 2024-03-14T11:53:44.423Z] 11:53:44     INFO -  _getSecurityAppData@resource://gre/modules/TelemetryEnvironment.sys.mjs:1990:36
[task 2024-03-14T11:53:44.423Z] 11:53:44     INFO -  _getSystem@resource://gre/modules/TelemetryEnvironment.sys.mjs:2096:23
[task 2024-03-14T11:53:44.423Z] 11:53:44     INFO -  EnvironmentCache@resource://gre/modules/TelemetryEnvironment.sys.mjs:977:18
[task 2024-03-14T11:53:44.423Z] 11:53:44     INFO -  getGlobal@resource://gre/modules/TelemetryEnvironment.sys.mjs:77:26
[task 2024-03-14T11:53:44.424Z] 11:53:44     INFO -  testCleanRestart@resource://gre/modules/TelemetryEnvironment.sys.mjs:201:12
[task 2024-03-14T11:53:44.424Z] 11:53:44     INFO -  test_environmentDidntChange@Z:/task_171041633923738/build/tests/xpcshell/tests/toolkit/components/telemetry/tests/unit/test_TelemetryEnvironment.js:1455:30
[task 2024-03-14T11:53:44.425Z] 11:53:44     INFO -  _run_next_test/<@Z:\\task_171041633923738\\build\\tests\\xpcshell\\head.js:1762:22
[task 2024-03-14T11:53:44.425Z] 11:53:44     INFO -  _run_next_test@Z:\\task_171041633923738\\build\\tests\\xpcshell\\head.js:1762:38
[task 2024-03-14T11:53:44.425Z] 11:53:44     INFO -  run@Z:\\task_171041633923738\\build\\tests\\xpcshell\\head.js:808:9
[task 2024-03-14T11:53:44.425Z] 11:53:44     INFO -  _do_main@Z:\\task_171041633923738\\build\\tests\\xpcshell\\head.js:245:6
[task 2024-03-14T11:53:44.426Z] 11:53:44     INFO -  _execute_test@Z:\\task_171041633923738\\build\\tests\\xpcshell\\head.js:596:5
[task 2024-03-14T11:53:44.426Z] 11:53:44     INFO -  @-e:1:1
[task 2024-03-14T11:53:44.426Z] 11:53:44     INFO -  "
[task 2024-03-14T11:53:44.426Z] 11:53:44     INFO -  "CONSOLE_MESSAGE: (info) 1710417222138	Toolkit.Telemetry	TRACE	TelemetryEnvironment::_updateSearchEngine - ignoring early call"
<...>
INFO -  "CONSOLE_MESSAGE: (info) 1710417222280	Toolkit.Telemetry	TRACE	TelemetryEnvironment::observe - aTopic: browser-search-service, aData: settings-update-complete"
[task 2024-03-14T11:53:44.482Z] 11:53:44     INFO -  PID 9592 | JavaScript error: resource://gre/modules/SearchService.sys.mjs, line 1391: NS_ERROR_ABORT: #init: abandoning init due to shutting down
[task 2024-03-14T11:53:44.482Z] 11:53:44     INFO -  PID 9592 | JavaScript error: resource://gre/modules/SearchService.sys.mjs, line 1391: NS_ERROR_ABORT: #init: abandoning init due to shutting down
[task 2024-03-14T11:53:44.482Z] 11:53:44     INFO -  PID 9592 | JavaScript error: resource://gre/modules/SearchService.sys.mjs, line 1391: NS_ERROR_ABORT: #init: abandoning init due to shutting down
[task 2024-03-14T11:53:44.483Z] 11:53:44     INFO -  "CONSOLE_MESSAGE: (error) [JavaScript Error: "NS_ERROR_ABORT: #init: abandoning init due to shutting down" {file: "resource://gre/modules/SearchService.sys.mjs" line: 1391}]"
[task 2024-03-14T11:53:44.483Z] 11:53:44     INFO -  "CONSOLE_MESSAGE: (error) [JavaScript Error: "NS_ERROR_ABORT: #init: abandoning init due to shutting down" {file: "resource://gre/modules/SearchService.sys.mjs" line: 1391}]"
[task 2024-03-14T11:53:44.483Z] 11:53:44     INFO -  "CONSOLE_MESSAGE: (error) [JavaScript Error: "NS_ERROR_ABORT: #init: abandoning init due to shutting down" {file: "resource://gre/modules/SearchService.sys.mjs" line: 1391}]"
[task 2024-03-14T11:53:44.483Z] 11:53:44  WARNING -  TEST-UNEXPECTED-FAIL | toolkit/components/telemetry/tests/unit/test_TelemetryEnvironment.js | test_environmentDidntChange - [test_environmentDidntChange : 266] A promise chain failed to handle a rejection: #init: abandoning init due to shutting down - stack: #init@resource://gre/modules/SearchService.sys.mjs:1391:27
[task 2024-03-14T11:53:44.484Z] 11:53:44     INFO -  observe@resource://gre/modules/AsyncShutdown.sys.mjs:570:17
[task 2024-03-14T11:53:44.484Z] 11:53:44     INFO -  _execute_test@Z:\\task_171041633923738\\build\\tests\\xpcshell\\head.js:707:23
[task 2024-03-14T11:53:44.484Z] 11:53:44     INFO -  @-e:1:1
[task 2024-03-14T11:53:44.485Z] 11:53:44     INFO -  Rejection date: Thu Mar 14 2024 11:53:42 GMT+0000 (Coordinated Universal Time) - false == true
[task 2024-03-14T11:53:44.485Z] 11:53:44     INFO -  resource://testing-common/PromiseTestUtils.sys.mjs:assertNoUncaughtRejections:266
[task 2024-03-14T11:53:44.485Z] 11:53:44     INFO -  Z:\task_171041633923738\build\tests\xpcshell\head.js:_execute_test:722
[task 2024-03-14T11:53:44.485Z] 11:53:44     INFO -  -e:null:1
[task 2024-03-14T11:53:44.485Z] 11:53:44     INFO -  exiting test
[task 2024-03-14T11:53:44.485Z] 11:53:44     INFO -  PID 9592 | JavaScript error: Z:\\task_171041633923738\\build\\tests\\xpcshell\\head.js, line 869: NS_ERROR_ABORT:
[task 2024-03-14T11:53:44.486Z] 11:53:44     INFO -  <<<<<<<
[task 2024-03-14T11:53:44.502Z] 11:53:44     INFO -  TEST-START | toolkit/components/telemetry/tests/unit/test_UserInteraction_annotations.js

The recent spate of intermittents appears to be triggered by some code introduced in bug 1849013 throwing an exception for init'ing during shutdown. However, I can't tell from the logs what is init'ing the search service during that test.

More precisely, I can't tell what's init'ing the search service nine times in a row.

Let's see if it's reproducible locally...

Assignee: nobody → chutten
Status: NEW → ASSIGNED
Keywords: regression
Priority: P5 → P1
Regressed by: 1849013

Set release status flags based on info from the regressing bug 1849013

It does reproduce locally, which is helpful. I turned on the SearchService logging and found that the test suite does indeed init the SearchService wayyyy back in test_delayed_defaultBrowser on its notification of "sessionstore-windows-restored". The observation of which by TelemetryEnvironment triggers Services.search.init() since bug 1359031.

SearchService's init is async, so if it doesn't happen to complete until we happen to be in shutdown in, say, test_environmentDidntChange, bug 1849013 means it throws an exception. It does this off in async land, which is why the stack is particularly unhelpful.

A way to solve this would be to await Services.search.promiseInitialized; back in test_delayed_defaultBrowser thereby ensuring that this code is a little more deterministic. There might be another way that will read a little more nicely in the test, but I'm happy to write a short essay to explain what's going on.

Pushed by chutten@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/c72df5bb4fe1 Await SearchService init in TelemetryEnvironment test r=janerik,mcheang
Status: ASSIGNED → RESOLVED
Closed: 3 months ago
Resolution: --- → FIXED
Target Milestone: --- → 130 Branch

Set release status flags based on info from the regressing bug 1849013

You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: