Intermittent toolkit/components/telemetry/tests/unit/test_TelemetryEnvironment.js | single tracking bug
Categories
(Toolkit :: Telemetry, defect, P1)
Tracking
()
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
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Assignee | ||
Comment 17•4 months ago
|
||
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...
Comment 18•4 months ago
|
||
Set release status flags based on info from the regressing bug 1849013
Assignee | ||
Comment 19•4 months ago
|
||
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.
Assignee | ||
Comment 20•4 months ago
|
||
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 23•3 months ago
|
||
Comment 24•3 months ago
|
||
bugherder |
Comment 25•3 months ago
|
||
Set release status flags based on info from the regressing bug 1849013
Comment 26•3 months ago
|
||
uplift |
Updated•3 months ago
|
Comment hidden (Intermittent Failures Robot) |
Updated•3 months ago
|
Comment 28•3 months ago
|
||
uplift |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Description
•