1897331 - Intermittent TV1 TEST-UNEXPECTED-TIMEOUT | toolkit/mozapps/update/tests/unit_aus_update/ensureExperimentToRolloutTransitionPerformed.js | Test timed out

Status: RESOLVED FIXED

(Toolkit :: Application Update, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: tszentpeteri [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=458520887&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/UJuSHGyyTqqVeKj4blqjoA/runs/0/artifacts/public/logs/live_backing.log
Reftest URL: https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/UJuSHGyyTqqVeKj4blqjoA/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

---

[task 2024-05-16T21:05:15.143Z] 21:05:15     INFO -  TEST-START | toolkit/mozapps/update/tests/unit_aus_update/ensureExperimentToRolloutTransitionPerformed.js
[task 2024-05-16T21:10:15.145Z] 21:10:15  WARNING -  TEST-UNEXPECTED-TIMEOUT | toolkit/mozapps/update/tests/unit_aus_update/ensureExperimentToRolloutTransitionPerformed.js | Test timed out
[task 2024-05-16T21:10:15.146Z] 21:10:15     INFO -  TEST-INFO took 300002ms
[task 2024-05-16T21:10:15.146Z] 21:10:15     INFO -  >>>>>>>
[task 2024-05-16T21:10:15.147Z] 21:10:15     INFO -  PID 7756 | DLL blocklist was unable to intercept AppInit DLLs.
[task 2024-05-16T21:10:15.147Z] 21:10:15     INFO -  PID 7756 | Couldn't convert chrome URL: chrome://branding/locale/brand.properties
[task 2024-05-16T21:10:15.147Z] 21:10:15     INFO -  PID 7756 | [Parent 7756, Main Thread] WARNING: Failed to get directory to cache.: file /builds/worker/checkouts/gecko/security/sandbox/win/src/sandboxbroker/sandboxBroker.cpp:148
[task 2024-05-16T21:10:15.148Z] 21:10:15     INFO -  PID 7756 | [Parent 7756, Main Thread] WARNING: Failed to get directory to cache.: file /builds/worker/checkouts/gecko/security/sandbox/win/src/sandboxbroker/sandboxBroker.cpp:148
[task 2024-05-16T21:10:15.148Z] 21:10:15     INFO -  PID 7756 | [Parent 7756, Main Thread] WARNING: Couldn't get the user appdata directory. Crash events may not be produced.: file /builds/worker/checkouts/gecko/toolkit/crashreporter/nsExceptionHandler.cpp:2925
[task 2024-05-16T21:10:15.148Z] 21:10:15     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2024-05-16T21:10:15.149Z] 21:10:15     INFO -  "21:05:15:365 | TEST-INFO | xpcshellUtilsAUS.js | [setupTestCommon : 883] start - general test setup"
[task 2024-05-16T21:10:15.149Z] 21:10:15     INFO -  TEST-PASS | toolkit/mozapps/update/tests/unit_aus_update/ensureExperimentToRolloutTransitionPerformed.js | setupTestCommon - [setupTestCommon : 885] gTestID should be 'undefined' (setupTestCommon should only be called once) - "undefined" === "undefined"
[task 2024-05-16T21:10:15.149Z] 21:10:15     INFO -  (xpcshell/head.js) | test pending (2)
[task 2024-05-16T21:10:15.150Z] 21:10:15     INFO -  "21:05:15:373 | TEST-INFO | xpcshellUtilsAUS.js | [runTestHelperSync : 2216] Running D:\\task_171588968238908\\build\\tests\\xpcshell\\tests\\toolkit\\mozapps\\update\\tests\\data\\TestAUSHelper.exe create-update-dir D:\\task_171588968238908\\build\\tests\\xpcshell\\tests\\toolkit\\mozapps\\update\\tests\\unit_aus_update\\ensureExperimentToRolloutTransitionPerformed\\dir.app"
[task 2024-05-16T21:10:15.150Z] 21:10:15     INFO -  TEST-PASS | toolkit/mozapps/update/tests/unit_aus_update/ensureExperimentToRolloutTransitionPerformed.js | createWorldWritableAppUpdateDir - [createWorldWritableAppUpdateDir : 1827] The helper process exit value should be 0 - 0 == 0
[task 2024-05-16T21:10:15.151Z] 21:10:15     INFO -  "21:05:15:445 | TEST-INFO | xpcshellUtilsAUS.js | [getSpecialFolderDir : 1679] SHGetSpecialFolderPath returned path: C:\\ProgramData"
[task 2024-05-16T21:10:15.151Z] 21:10:15     INFO -  "21:05:15:446 | TEST-INFO | xpcshellUtilsAUS.js | [setupTestCommon : 979] Updates Directory (UpdRootD) Path: C:\\ProgramData\\Mozilla-1de4eec8-1241-4177-a864-e594e8d1fb38\\updates\\ensureExperimentToRolloutTransitionPerformed"
[task 2024-05-16T21:10:15.151Z] 21:10:15     INFO -  "21:05:15:448 | TEST-INFO | xpcshellUtilsAUS.js | [setupTestCommon : 996] resetting update lock"
[task 2024-05-16T21:10:15.152Z] 21:10:15     INFO -  PID 7756 | [Parent 7756, Main Thread] WARNING: Failed to resolve install directory.: file /builds/worker/checkouts/gecko/toolkit/xre/MultiInstanceLock.cpp:279
[task 2024-05-16T21:10:15.152Z] 21:10:15     INFO -  "21:05:15:450 | TEST-INFO | xpcshellUtilsAUS.js | [setupTestCommon : 1026] finish - general test setup"
[task 2024-05-16T21:10:15.152Z] 21:10:15     INFO -  PID 7756 | [Parent 7756, Main Thread] WARNING: '!mColorFilterWatcher', file /builds/worker/checkouts/gecko/widget/windows/nsLookAndFeel.cpp:69
[task 2024-05-16T21:10:15.152Z] 21:10:15     INFO -  PID 7756 | *** AUS:STB UpdateServiceStub - Begin (force_update_init=false)
[task 2024-05-16T21:10:15.153Z] 21:10:15     INFO -  PID 7756 | *** AUS:STB UpdateServiceStub:migrateUpdateDirectory Performing migration
[task 2024-05-16T21:10:15.153Z] 21:10:15     INFO -  (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2024-05-16T21:10:15.153Z] 21:10:15     INFO -  running event loop
[task 2024-05-16T21:10:15.154Z] 21:10:15     INFO -  PID 7756 | [Parent 7756, Main Thread] WARNING: Could not get the program name for a cubeb stream.: 'NS_SUCCEEDED(rv)', file /builds/worker/checkouts/gecko/dom/media/CubebUtils.cpp:467
[task 2024-05-16T21:10:15.154Z] 21:10:15     INFO -  PID 7756 | [Parent 7756, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111 (NS_ERROR_NOT_AVAILABLE): file /builds/worker/checkouts/gecko/startupcache/StartupCacheUtils.cpp:154
[task 2024-05-16T21:10:15.155Z] 21:10:15     INFO -  PID 7756 | [Parent 7756, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111 (NS_ERROR_NOT_AVAILABLE): file /builds/worker/checkouts/gecko/js/xpconnect/loader/mozJSModuleLoader.cpp:909
[task 2024-05-16T21:10:15.155Z] 21:10:15     INFO -  PID 7756 | [Parent 7756, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111 (NS_ERROR_NOT_AVAILABLE): file /builds/worker/checkouts/gecko/js/loader/ModuleLoaderBase.cpp:475
[task 2024-05-16T21:10:15.155Z] 21:10:15     INFO -  PID 7756 | JavaScript error: D:/task_171588968238908/build/tests/xpcshell/tests/toolkit/mozapps/update/tests/unit_aus_update/ensureExperimentToRolloutTransitionPerformed.js, line 26: Error: Failed to load resource://devtools/shared/security/DevToolsSocketStatus.sys.mjs
[task 2024-05-16T21:10:15.156Z] 21:10:15     INFO -  "CONSOLE_MESSAGE: (error) [JavaScript Error: "Error: Failed to load resource://devtools/shared/security/DevToolsSocketStatus.sys.mjs" {file: "D:/task_171588968238908/build/tests/xpcshell/tests/toolkit/mozapps/update/tests/unit_aus_update/ensureExperimentToRolloutTransitionPerformed.js" line: 26}]"
[task 2024-05-16T21:10:15.156Z] 21:10:15     INFO -  <<<<<<<
[task 2024-05-16T21:10:15.270Z] 21:10:15     INFO -  xpcshell return code: None
[task 2024-05-16T21:10:15.286Z] 21:10:15     INFO -  TEST-START | toolkit/mozapps/update/tests/unit_aus_update/ensureExperimentToRolloutTransitionPerformed.js

Comment 1

[BugBot [:suhaib / :marco/ :calixte]]

:bytesized, since you are the author of the regressor, bug 1875502, could you take a look?

For more information, please visit BugBot documentation.

Comment 2

[BugBot [:suhaib / :marco/ :calixte]]

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

Comment 3

[Robin Steuber (she/her) [:bytesized]]

Investigating.

Comment 4

[Robin Steuber (she/her) [:bytesized]]

I actually do not think this is my doing.

The relevant bit of the test log seems to be this:

[task 2024-05-16T21:10:15.155Z] 21:10:15     INFO -  PID 7756 | JavaScript error: D:/task_171588968238908/build/tests/xpcshell/tests/toolkit/mozapps/update/tests/unit_aus_update/ensureExperimentToRolloutTransitionPerformed.js, line 26: Error: Failed to load resource://devtools/shared/security/DevToolsSocketStatus.sys.mjs
[task 2024-05-16T21:10:15.156Z] 21:10:15     INFO -  "CONSOLE_MESSAGE: (error) [JavaScript Error: "Error: Failed to load resource://devtools/shared/security/DevToolsSocketStatus.sys.mjs" {file: "D:/task_171588968238908/build/tests/xpcshell/tests/toolkit/mozapps/update/tests/unit_aus_update/ensureExperimentToRolloutTransitionPerformed.js" line: 26}]"

It would be nice if there were more of, like, a complete stack trace of this error. But even without one this doesn't really make a lot of sense. In my local copy of the patch stack, DevToolsSocketStatus.sys.mjs isn't imported by anything that this code should logically use. However, when I look at the state of the repository when this test failure occurred, I can see that we do import DevToolsSocketStatus.sys.mjs. Consulting the blame annotations shows that this addition came from Bug 1833735.

---

As an aside, I couldn't help but notice when I was poking around here that when the relevant test, ensureExperimentToRolloutTransitionPerformed.js, calls BackgroundUpdate.ensureExperimentToRolloutTransitionPerformed(), it doesn't await on it. We should probably fix that.

Comment 5

[Iulian Moraru]

This is fixed by backout: https://hg.mozilla.org/integration/autoland/rev/571c0a8534bfa637dce800791cd385a96efb8224

Comment 6

[Intermittent Failures Robot]

1 failures in 4547 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• windows11-64-2009-qr: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1897331&startday=2024-05-13&endday=2024-05-19&tree=all