Closed Bug 1815524 Opened 2 years ago Closed 2 years ago

Frequent toolkit/modules/tests/xpcshell/test_firstStartup.js | single tracking bug

Categories

(Toolkit :: Find Toolbar, defect, P5)

defect

Tracking

()

RESOLVED FIXED
117 Branch
Tracking Status
firefox117 --- fixed

People

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

References

Details

(Keywords: intermittent-failure, intermittent-testcase)

Attachments

(1 file)

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


[task 2023-02-07T18:26:49.002Z] 18:26:49     INFO -  TEST-START | toolkit/modules/tests/xpcshell/test_Region_geocoding.js
[task 2023-02-07T18:27:07.120Z] 18:27:07     INFO -  TEST-PASS | toolkit/modules/tests/xpcshell/test_Region_geocoding.js | took 18119ms
[task 2023-02-07T18:27:07.135Z] 18:27:07     INFO -  Retrying tests that failed when run in parallel.
[task 2023-02-07T18:27:07.137Z] 18:27:07     INFO -  TEST-START | toolkit/modules/tests/xpcshell/test_firstStartup.js
[task 2023-02-07T18:27:18.749Z] 18:27:18  WARNING -  TEST-UNEXPECTED-FAIL | toolkit/modules/tests/xpcshell/test_firstStartup.js | xpcshell return code: 0
[task 2023-02-07T18:27:18.761Z] 18:27:18     INFO -  TEST-INFO took 11612ms
[task 2023-02-07T18:27:18.761Z] 18:27:18     INFO -  >>>>>>>
[task 2023-02-07T18:27:18.761Z] 18:27:18     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2023-02-07T18:27:18.761Z] 18:27:18     INFO -  (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2023-02-07T18:27:18.762Z] 18:27:18     INFO -  (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2023-02-07T18:27:18.762Z] 18:27:18     INFO -  running event loop
[task 2023-02-07T18:27:18.762Z] 18:27:18     INFO -  toolkit/modules/tests/xpcshell/test_firstStartup.js | Starting test_success
[task 2023-02-07T18:27:18.762Z] 18:27:18     INFO -  (xpcshell/head.js) | test test_success pending (2)
[task 2023-02-07T18:27:18.763Z] 18:27:18     INFO -  PID 6688 | console.error: (new Error("Unexpected content-type \\"text/plain;charset=US-ASCII\\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-02-07T18:27:18.763Z] 18:27:18     INFO -  PID 6688 | console.error: (new Error("Unexpected content-type \\"text/plain;charset=US-ASCII\\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-02-07T18:27:18.763Z] 18:27:18     INFO -  PID 6688 | console.error: (new Error("Unexpected content-type \\"text/plain;charset=US-ASCII\\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-02-07T18:27:18.764Z] 18:27:18     INFO -  TEST-PASS | toolkit/modules/tests/xpcshell/test_firstStartup.js | test_success - [test_success : 19] 3 == 3
[task 2023-02-07T18:27:18.764Z] 18:27:18     INFO -  (xpcshell/head.js) | test run_next_test 0 finished (2)
[task 2023-02-07T18:27:18.764Z] 18:27:18     INFO -  (xpcshell/head.js) | test run_next_test 1 pending (2)
[task 2023-02-07T18:27:18.764Z] 18:27:18     INFO -  (xpcshell/head.js) | test test_success finished (2)
[task 2023-02-07T18:27:18.764Z] 18:27:18     INFO -  toolkit/modules/tests/xpcshell/test_firstStartup.js | Starting test_timeout
[task 2023-02-07T18:27:18.765Z] 18:27:18     INFO -  (xpcshell/head.js) | test test_timeout pending (2)
[task 2023-02-07T18:27:18.765Z] 18:27:18     INFO -  TEST-PASS | toolkit/modules/tests/xpcshell/test_firstStartup.js | test_timeout - [test_timeout : 31] 2 == 2
[task 2023-02-07T18:27:18.765Z] 18:27:18     INFO -  (xpcshell/head.js) | test run_next_test 1 finished (2)
[task 2023-02-07T18:27:18.765Z] 18:27:18     INFO -  (xpcshell/head.js) | test run_next_test 2 pending (2)
[task 2023-02-07T18:27:18.765Z] 18:27:18     INFO -  (xpcshell/head.js) | test test_timeout finished (2)
[task 2023-02-07T18:27:18.766Z] 18:27:18     INFO -  (xpcshell/head.js) | test run_next_test 2 finished (1)
[task 2023-02-07T18:27:18.766Z] 18:27:18     INFO -  exiting test
[task 2023-02-07T18:27:18.767Z] 18:27:18     INFO -  "CONSOLE_MESSAGE: (error) [JavaScript Error: "IndexedDB UnknownErr: ActorsParent.cpp:9566"]"
[task 2023-02-07T18:27:18.767Z] 18:27:18     INFO -  "CONSOLE_MESSAGE: (error) [JavaScript Error: "IndexedDB UnknownErr: ActorsParent.cpp:10263"]"
[task 2023-02-07T18:27:18.767Z] 18:27:18     INFO -  PID 6688 | *** UTM:SVC TimerManager:registerTimer called after profile-before-change notification. Ignoring timer registration for id: recipe-client-addon-run
[task 2023-02-07T18:27:18.768Z] 18:27:18     INFO -  "CONSOLE_MESSAGE: (error) [JavaScript Error: "1675794438692	app.normandy.bootstrap	ERROR	Failed to initialize addon rollouts:: AbortError: A request was aborted, for example through a call to IDBTransaction.abort. No traceback available" {file: "resource://gre/modules/Log.sys.mjs" line: 723}]
[task 2023-02-07T18:27:18.768Z] 18:27:18     INFO -  append@resource://gre/modules/Log.sys.mjs:723:12
[task 2023-02-07T18:27:18.768Z] 18:27:18     INFO -  log@resource://gre/modules/Log.sys.mjs:377:16
[task 2023-02-07T18:27:18.768Z] 18:27:18     INFO -  error@resource://gre/modules/Log.sys.mjs:385:10
[task 2023-02-07T18:27:18.769Z] 18:27:18     INFO -  finishInit@resource://normandy/Normandy.jsm:172:11
[task 2023-02-07T18:27:18.769Z] 18:27:18     INFO -  _execute_test@Z:\\task_167579070795972\\build\\tests\\xpcshell\\head.js:702:23
[task 2023-02-07T18:27:18.769Z] 18:27:18     INFO -  @-e:1:1
[task 2023-02-07T18:27:18.769Z] 18:27:18     INFO -  "
[task 2023-02-07T18:27:18.770Z] 18:27:18     INFO -  "CONSOLE_MESSAGE: (error) [JavaScript Error: "1675794438692	app.normandy.bootstrap	ERROR	Failed to initialize addon rollouts:: AbortError: A request was aborted, for example through a call to IDBTransaction.abort. No traceback available" {file: "resource://gre/modules/Log.sys.mjs" line: 723}]
[task 2023-02-07T18:27:18.770Z] 18:27:18     INFO -  append@resource://gre/modules/Log.sys.mjs:723:12
[task 2023-02-07T18:27:18.770Z] 18:27:18     INFO -  log@resource://gre/modules/Log.sys.mjs:377:16
[task 2023-02-07T18:27:18.770Z] 18:27:18     INFO -  error@resource://gre/modules/Log.sys.mjs:385:10
[task 2023-02-07T18:27:18.771Z] 18:27:18     INFO -  finishInit@resource://normandy/Normandy.jsm:172:11
[task 2023-02-07T18:27:18.771Z] 18:27:18     INFO -  _execute_test@Z:\\task_167579070795972\\build\\tests\\xpcshell\\head.js:702:23
[task 2023-02-07T18:27:18.771Z] 18:27:18     INFO -  @-e:1:1
[task 2023-02-07T18:27:18.771Z] 18:27:18     INFO -  "
[task 2023-02-07T18:27:18.771Z] 18:27:18     INFO -  "CONSOLE_MESSAGE: (error) [JavaScript Error: "1675794438692	app.normandy.bootstrap	ERROR	Failed to initialize addon rollouts:: AbortError: A request was aborted, for example through a call to IDBTransaction.abort. No traceback available" {file: "resource://gre/modules/Log.sys.mjs" line: 723}]
[task 2023-02-07T18:27:18.772Z] 18:27:18     INFO -  append@resource://gre/modules/Log.sys.mjs:723:12
[task 2023-02-07T18:27:18.772Z] 18:27:18     INFO -  log@resource://gre/modules/Log.sys.mjs:377:16
[task 2023-02-07T18:27:18.772Z] 18:27:18     INFO -  error@resource://gre/modules/Log.sys.mjs:385:10
[task 2023-02-07T18:27:18.772Z] 18:27:18     INFO -  finishInit@resource://normandy/Normandy.jsm:172:11
[task 2023-02-07T18:27:18.773Z] 18:27:18     INFO -  _execute_test@Z:\\task_167579070795972\\build\\tests\\xpcshell\\head.js:702:23
[task 2023-02-07T18:27:18.773Z] 18:27:18     INFO -  @-e:1:1
[task 2023-02-07T18:27:18.773Z] 18:27:18     INFO -  "
[task 2023-02-07T18:27:18.773Z] 18:27:18     INFO -  "CONSOLE_MESSAGE: (error) [JavaScript Error: "1675794438693	app.normandy.bootstrap	ERROR	Failed to initialize preference experiments:: Error: Data is not ready.(resource://gre/modules/JSONFile.sys.mjs:184:13) JS Stack trace: get data@sys.mjs:184:13
[task 2023-02-07T18:27:18.773Z] 18:27:18     INFO -  getAllActive@PreferenceExperiments.jsm:924:5
[task 2023-02-07T18:27:18.774Z] 18:27:18     INFO -  _execute_test@Z:\\task_167579070795972\\build\\tests\\xpcshell\\head.js:702:23
[task 2023-02-07T18:27:18.774Z] 18:27:18     INFO -  @-e:1:1" {file: "resource://gre/modules/Log.sys.mjs" line: 723}]
[task 2023-02-07T18:27:18.775Z] 18:27:18     INFO -  append@resource://gre/modules/Log.sys.mjs:723:12
[task 2023-02-07T18:27:18.775Z] 18:27:18     INFO -  log@resource://gre/modules/Log.sys.mjs:377:16
[task 2023-02-07T18:27:18.775Z] 18:27:18     INFO -  error@resource://gre/modules/Log.sys.mjs:385:10
[task 2023-02-07T18:27:18.775Z] 18:27:18     INFO -  finishInit@resource://normandy/Normandy.jsm:178:11
[task 2023-02-07T18:27:18.775Z] 18:27:18     INFO -  _execute_test@Z:\\task_167579070795972\\build\\tests\\xpcshell\\head.js:702:23
[task 2023-02-07T18:27:18.775Z] 18:27:18     INFO -  @-e:1:1
[task 2023-02-07T18:27:18.776Z] 18:27:18     INFO -  "
[task 2023-02-07T18:27:18.776Z] 18:27:18     INFO -  "CONSOLE_MESSAGE: (error) [JavaScript Error: "1675794438693	app.normandy.bootstrap	ERROR	Failed to initialize preference experiments:: Error: Data is not ready.(resource://gre/modules/JSONFile.sys.mjs:184:13) JS Stack trace: get data@sys.mjs:184:13
[task 2023-02-07T18:27:18.776Z] 18:27:18     INFO -  getAllActive@PreferenceExperiments.jsm:924:5
[task 2023-02-07T18:27:18.776Z] 18:27:18     INFO -  _execute_test@Z:\\task_167579070795972\\build\\tests\\xpcshell\\head.js:702:23
[task 2023-02-07T18:27:18.777Z] 18:27:18     INFO -  @-e:1:1" {file: "resource://gre/modules/Log.sys.mjs" line: 723}]
[task 2023-02-07T18:27:18.777Z] 18:27:18     INFO -  append@resource://gre/modules/Log.sys.mjs:723:12
[task 2023-02-07T18:27:18.777Z] 18:27:18     INFO -  log@resource://gre/modules/Log.sys.mjs:377:16
[task 2023-02-07T18:27:18.777Z] 18:27:18     INFO -  error@resource://gre/modules/Log.sys.mjs:385:10
[task 2023-02-07T18:27:18.777Z] 18:27:18     INFO -  finishInit@resource://normandy/Normandy.jsm:178:11
[task 2023-02-07T18:27:18.778Z] 18:27:18     INFO -  _execute_test@Z:\\task_167579070795972\\build\\tests\\xpcshell\\head.js:702:23
[task 2023-02-07T18:27:18.778Z] 18:27:18     INFO -  @-e:1:1
[task 2023-02-07T18:27:18.778Z] 18:27:18     INFO -  "
[task 2023-02-07T18:27:18.778Z] 18:27:18     INFO -  "CONSOLE_MESSAGE: (error) [JavaScript Error: "1675794438693	app.normandy.bootstrap	ERROR	Failed to initialize preference experiments:: Error: Data is not ready.(resource://gre/modules/JSONFile.sys.mjs:184:13) JS Stack trace: get data@sys.mjs:184:13
[task 2023-02-07T18:27:18.779Z] 18:27:18     INFO -  getAllActive@PreferenceExperiments.jsm:924:5
[task 2023-02-07T18:27:18.779Z] 18:27:18     INFO -  _execute_test@Z:\\task_167579070795972\\build\\tests\\xpcshell\\head.js:702:23
[task 2023-02-07T18:27:18.779Z] 18:27:18     INFO -  @-e:1:1" {file: "resource://gre/modules/Log.sys.mjs" line: 723}]
[task 2023-02-07T18:27:18.779Z] 18:27:18     INFO -  append@resource://gre/modules/Log.sys.mjs:723:12
[task 2023-02-07T18:27:18.779Z] 18:27:18     INFO -  log@resource://gre/modules/Log.sys.mjs:377:16
[task 2023-02-07T18:27:18.780Z] 18:27:18     INFO -  error@resource://gre/modules/Log.sys.mjs:385:10
[task 2023-02-07T18:27:18.780Z] 18:27:18     INFO -  finishInit@resource://normandy/Normandy.jsm:178:11
[task 2023-02-07T18:27:18.780Z] 18:27:18     INFO -  _execute_test@Z:\\task_167579070795972\\build\\tests\\xpcshell\\head.js:702:23
[task 2023-02-07T18:27:18.780Z] 18:27:18     INFO -  @-e:1:1
[task 2023-02-07T18:27:18.780Z] 18:27:18     INFO -  "
[task 2023-02-07T18:27:18.781Z] 18:27:18     INFO -  "CONSOLE_MESSAGE: (info) UTM:SVC TimerManager:registerTimer called after profile-before-change notification. Ignoring timer registration for id: recipe-client-addon-run"
[task 2023-02-07T18:27:18.782Z] 18:27:18     INFO -  PID 6688 | JavaScript error: , line 0: AbortError: A request was aborted, for example through a call to IDBTransaction.abort.
[task 2023-02-07T18:27:18.782Z] 18:27:18     INFO -  "CONSOLE_MESSAGE: (error) [JavaScript Error: "AbortError: A request was aborted, for example through a call to IDBTransaction.abort."]"
[task 2023-02-07T18:27:18.782Z] 18:27:18  WARNING -  TEST-UNEXPECTED-FAIL | toolkit/modules/tests/xpcshell/test_firstStartup.js | test_timeout - [test_timeout : 266] A promise chain failed to handle a rejection: A request was aborted, for example through a call to IDBTransaction.abort. - stack: (No stack available.)
[task 2023-02-07T18:27:18.783Z] 18:27:18     INFO -  Rejection date: Tue Feb 07 2023 18:27:18 GMT+0000 (Greenwich Mean Time) - false == true
[task 2023-02-07T18:27:18.783Z] 18:27:18     INFO -  resource://testing-common/PromiseTestUtils.sys.mjs:assertNoUncaughtRejections:266
[task 2023-02-07T18:27:18.783Z] 18:27:18     INFO -  Z:\task_167579070795972\build\tests\xpcshell\head.js:_execute_test:711
[task 2023-02-07T18:27:18.783Z] 18:27:18     INFO -  -e:null:1
[task 2023-02-07T18:27:18.783Z] 18:27:18     INFO -  exiting test
[task 2023-02-07T18:27:18.784Z] 18:27:18     INFO -  PID 6688 | JavaScript error: Z:\\task_167579070795972\\build\\tests\\xpcshell\\head.js, line 863: NS_ERROR_ABORT:
[task 2023-02-07T18:27:18.784Z] 18:27:18     INFO -  <<<<<<<
[task 2023-02-07T18:27:18.784Z] 18:27:18     INFO -  TEST-START | toolkit/components/antitracking/test/xpcshell/test_purge_trackers.js

The Bugbug bot thinks this bug should belong to the 'Toolkit::Find Toolbar' component, and is moving the bug to that component. Please correct in case you think the bot is wrong.

Component: General → Find Toolbar

Hi Mike! Can you please take a look at this? This seems to have started with the landing of Bug 1841138.
This is now frequently failing with this failure line TEST-UNEXPECTED-FAIL | toolkit/modules/tests/xpcshell/test_firstStartup.js | test_timeout - [test_timeout : 78] false == true
Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=421532251&repo=autoland&lineNumber=6568
Thank you!

Flags: needinfo?(mconley)
Summary: Intermittent toolkit/modules/tests/xpcshell/test_firstStartup.js | single tracking bug → Frequent toolkit/modules/tests/xpcshell/test_firstStartup.js | single tracking bug
Assignee: nobody → mconley
Flags: needinfo?(mconley)

This is because sometimes these timings will be less than 1 millisecond, and we
were coercing those fractional numbers to a uint which caused it to become 0.

This patch causes us to round up to the nearest uint instead.

It also adds the AppConstants.MOZ_NORMANDY condition for recording the timing
value for Normandy init, which I'd somehow missed the first time.

Pushed by sstanca@mozilla.com: https://hg.mozilla.org/mozilla-central/rev/6e7721ce3924 Round up FirstStartup timing probes to the nearest uint. r=rhelmer
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
Target Milestone: --- → 117 Branch

Nice! I was hitting this frequently while working on something totally different. Time to rebase my patches. Thanks!

Blocks: 1839051
See Also: → 1865088
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: