Closed Bug 1877654 Opened 10 months ago Closed 9 months ago

Perma OSX toolkit/mozapps/update/tests/unit_base_updater/marSuccessPartialWhileBackgroundTaskRunning.js | run_test - [run_test : 74] 11 == -9 | assertNoUncaughtRejections - [assertNoUncaughtRejections : 266] A promise chain failed to handle a rejection:

Categories

(Toolkit :: Application Update, defect, P5)

Product:
Toolkit
Component:
Application Update
Type:
defect

Tracking

()

Status:
RESOLVED INCOMPLETE
Tracking Flags:
Tracking Status
firefox-esr115 --- unaffected
firefox122 --- unaffected
firefox123 --- unaffected
firefox124 --- wontfix

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Regression)

Details

(Keywords: intermittent-failure, intermittent-testcase, regression)

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

task 2024-01-31T08:11:27.922Z] 08:11:27     INFO -  TEST-START | toolkit/mozapps/update/tests/unit_base_updater/marSuccessPartialWhileBackgroundTaskRunning.js
[task 2024-01-31T08:11:28.271Z] 08:11:28  WARNING -  TEST-UNEXPECTED-FAIL | toolkit/mozapps/update/tests/unit_base_updater/marSuccessPartialWhileBackgroundTaskRunning.js | xpcshell return code: 0
[task 2024-01-31T08:11:28.271Z] 08:11:28     INFO -  TEST-INFO took 349ms
[task 2024-01-31T08:11:28.271Z] 08:11:28     INFO -  >>>>>>>
[task 2024-01-31T08:11:28.271Z] 08:11:28     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2024-01-31T08:11:28.271Z] 08:11:28     INFO -  "08:11:28:010 | TEST-INFO | xpcshellUtilsAUS.js | [setupTestCommon : 838] start - general test setup"
[task 2024-01-31T08:11:28.271Z] 08:11:28     INFO -  TEST-PASS | toolkit/mozapps/update/tests/unit_base_updater/marSuccessPartialWhileBackgroundTaskRunning.js | setupTestCommon - [setupTestCommon : 840] gTestID should be 'undefined' (setupTestCommon should only be called once) - "undefined" === "undefined"
[task 2024-01-31T08:11:28.272Z] 08:11:28     INFO -  (xpcshell/head.js) | test pending (2)
[task 2024-01-31T08:11:28.272Z] 08:11:28     INFO -  "08:11:28:011 | TEST-INFO | xpcshellUtilsAUS.js | [setupTestCommon : 934] Updates Directory (UpdRootD) Path: /Users/cltbld/Library/Caches/Mozilla/updates/opt/worker/tasks/task_170668836657033/build/tests/xpcshell/tests/toolkit/mozapps/update/tests/unit_base_updater/marSuccessPartialWhileBackgroundTaskRunning/dir"
[task 2024-01-31T08:11:28.272Z] 08:11:28     INFO -  "08:11:28:011 | TEST-INFO | xpcshellUtilsAUS.js | [setupTestCommon : 951] resetting update lock"
[task 2024-01-31T08:11:28.272Z] 08:11:28     INFO -  "08:11:28:011 | TEST-INFO | xpcshellUtilsAUS.js | [setupTestCommon : 964] attempting to remove directory. Path: /Users/cltbld/Library/Caches/Mozilla/updates/opt/worker/tasks/task_170668836657033/build/tests/xpcshell/tests/toolkit/mozapps/update/tests/unit_base_updater/marSuccessPartialWhileBackgroundTaskRunning/dir"
[task 2024-01-31T08:11:28.272Z] 08:11:28     INFO -  "08:11:28:011 | TEST-INFO | shared.js | [removeDirRecursive : 601] attempting to remove directory. Path: /Users/cltbld/Library/Caches/Mozilla/updates/opt/worker/tasks/task_170668836657033/build/tests/xpcshell/tests/toolkit/mozapps/update/tests/unit_base_updater/marSuccessPartialWhileBackgroundTaskRunning/dir"
[task 2024-01-31T08:11:28.272Z] 08:11:28     INFO -  "08:11:28:012 | TEST-INFO | xpcshellUtilsAUS.js | [setupTestCommon : 981] finish - general test setup"
[task 2024-01-31T08:11:28.272Z] 08:11:28     INFO -  TEST-PASS | toolkit/mozapps/update/tests/unit_base_updater/marSuccessPartialWhileBackgroundTaskRunning.js | run_test - [run_test : 49] "channel-prefs.js" == "channel-prefs.js"
[task 2024-01-31T08:11:28.272Z] 08:11:28     INFO -  "08:11:28:012 | TEST-INFO | xpcshellUtilsAUS.js | [setupUpdaterTest : 3133] start - updater test setup"
<...>
[task 2024-01-31T08:11:28.282Z] 08:11:28     INFO -  "08:11:28:021 | TEST-INFO | xpcshellUtilsAUS.js | [SUT_TD_FE : 3202] start - setup test directory: Contents/Resources/1/"
[task 2024-01-31T08:11:28.282Z] 08:11:28     INFO -  "08:11:28:021 | TEST-INFO | xpcshellUtilsAUS.js | [SUT_TD_FE : 3242] finish - setup test directory: Contents/Resources/1/"
[task 2024-01-31T08:11:28.283Z] 08:11:28     INFO -  PID 4546 | *** AUS:SVC readStatusFile - status: pending, path: /Users/cltbld/Library/Caches/Mozilla/updates/opt/worker/tasks/task_170668836657033/build/tests/xpcshell/tests/toolkit/mozapps/update/tests/unit_base_updater/marSuccessPartialWhileBackgroundTaskRunning/dir/updates/0/update.status
[task 2024-01-31T08:11:28.283Z] 08:11:28     INFO -  PID 4546 | *** AUS:SVC UpdateManager:UpdateManager - status = "pending"
[task 2024-01-31T08:11:28.283Z] 08:11:28     INFO -  PID 4546 | *** AUS:SVC UpdateManager:UpdateManager - Initialized downloadingUpdate to null
[task 2024-01-31T08:11:28.283Z] 08:11:28     INFO -  PID 4546 | *** AUS:SVC UpdateManager:UpdateManager - Initialized readyUpdate to [object Object]
[task 2024-01-31T08:11:28.283Z] 08:11:28     INFO -  PID 4546 | *** AUS:SVC UpdateManager:UpdateManager - Initialized readyUpdate state to pending
[task 2024-01-31T08:11:28.283Z] 08:11:28     INFO -  PID 4546 | *** AUS:SVC UpdateManager:observe - Reloading update data.
[task 2024-01-31T08:11:28.283Z] 08:11:28     INFO -  PID 4546 | *** AUS:SVC transitionState - Not transitioning state because it isn't changing.
[task 2024-01-31T08:11:28.283Z] 08:11:28     INFO -  PID 4546 | *** AUS:SVC readStatusFile - status: pending, path: /Users/cltbld/Library/Caches/Mozilla/updates/opt/worker/tasks/task_170668836657033/build/tests/xpcshell/tests/toolkit/mozapps/update/tests/unit_base_updater/marSuccessPartialWhileBackgroundTaskRunning/dir/updates/0/update.status
[task 2024-01-31T08:11:28.283Z] 08:11:28     INFO -  PID 4546 | *** AUS:SVC UpdateManager:observe - Got status = pending
[task 2024-01-31T08:11:28.283Z] 08:11:28     INFO -  PID 4546 | *** AUS:SVC Creating UpdateService
[task 2024-01-31T08:11:28.283Z] 08:11:28     INFO -  PID 4546 | *** AUS:SVC Logging current UpdateService status:
[task 2024-01-31T08:11:28.283Z] 08:11:28     INFO -  PID 4546 | *** AUS:SVC UpdateService.canUsuallyCheckForUpdates - able to check for updates
[task 2024-01-31T08:11:28.283Z] 08:11:28     INFO -  PID 4546 | *** AUS:SVC UpdateService.canCheckForUpdates - able to check for updates
[task 2024-01-31T08:11:28.283Z] 08:11:28     INFO -  PID 4546 | *** AUS:SVC getCanApplyUpdates - testing write access /Users/cltbld/Library/Caches/Mozilla/updates/opt/worker/tasks/task_170668836657033/build/tests/xpcshell/tests/toolkit/mozapps/update/tests/unit_base_updater/marSuccessPartialWhileBackgroundTaskRunning/dir/update.test
[task 2024-01-31T08:11:28.284Z] 08:11:28     INFO -  PID 4546 | *** AUS:SVC getCanApplyUpdates - bypass the write since elevation can be used on Mac OS X
[task 2024-01-31T08:11:28.284Z] 08:11:28     INFO -  PID 4546 | *** AUS:SVC getCanStageUpdates - staging updates is disabled by preference app.update.staging.enabled
[task 2024-01-31T08:11:28.284Z] 08:11:28     INFO -  PID 4546 | *** AUS:SVC getElevationRequired - recursively testing write access on /opt/worker/tasks/task_170668836657033/build/tests/xpcshell/tests/toolkit/mozapps/update/tests/unit_base_updater/marSuccessPartialWhileBackgroundTaskRunning/dir.app
[task 2024-01-31T08:11:28.284Z] 08:11:28     INFO -  PID 4546 | *** AUS:SVC getElevationRequired - able to write to application bundle, elevation not required
[task 2024-01-31T08:11:28.284Z] 08:11:28     INFO -  PID 4546 | *** AUS:SVC Elevation required: false
[task 2024-01-31T08:11:28.284Z] 08:11:28     INFO -  PID 4546 | *** AUS:SVC Other instance of the application currently running: false
[task 2024-01-31T08:11:28.284Z] 08:11:28     INFO -  PID 4546 | *** AUS:SVC Downloading: false
[task 2024-01-31T08:11:28.284Z] 08:11:28     INFO -  PID 4546 | *** AUS:SVC End of UpdateService status
[task 2024-01-31T08:11:28.284Z] 08:11:28     INFO -  PID 4546 | *** AUS:SVC transitionState - "STATE_IDLE" -> "STATE_PENDING".
[task 2024-01-31T08:11:28.284Z] 08:11:28     INFO -  PID 4546 | *** AUS:SVC UpdateManager:_loadXMLFileIntoArray - XML file does not exist. path: /Users/cltbld/Library/Caches/Mozilla/updates/opt/worker/tasks/task_170668836657033/build/tests/xpcshell/tests/toolkit/mozapps/update/tests/unit_base_updater/marSuccessPartialWhileBackgroundTaskRunning/dir/updates.xml
[task 2024-01-31T08:11:28.284Z] 08:11:28     INFO -  PID 4546 | *** AUS:SVC UpdateManager:observe - Reloaded downloadingUpdate as null
[task 2024-01-31T08:11:28.284Z] 08:11:28     INFO -  PID 4546 | *** AUS:SVC UpdateManager:observe - Reloaded readyUpdate as [object Object]
[task 2024-01-31T08:11:28.284Z] 08:11:28     INFO -  PID 4546 | *** AUS:SVC UpdateManager:observe - Reloaded readyUpdate state as pending
[task 2024-01-31T08:11:28.285Z] 08:11:28     INFO -  TEST-PASS | toolkit/mozapps/update/tests/unit_base_updater/marSuccessPartialWhileBackgroundTaskRunning.js | setupActiveUpdate - [setupActiveUpdate : 2247] the ready update should be defined - true == true
[task 2024-01-31T08:11:28.285Z] 08:11:28     INFO -  "08:11:28:031 | TEST-INFO | xpcshellUtilsAUS.js | [setupAppFiles : 2475] start - copying or creating symlinks to application files for the test"
[task 2024-01-31T08:11:28.285Z] 08:11:28     INFO -  TEST-PASS | toolkit/mozapps/update/tests/unit_base_updater/marSuccessPartialWhileBackgroundTaskRunning.js | copyFileToTestAppDir - [copyFileToTestAppDir : 2626] the file or directory should exist, leafName: firefox - true == true
[task 2024-01-31T08:11:28.285Z] 08:11:28     INFO -  TEST-PASS | toolkit/mozapps/update/tests/unit_base_updater/marSuccessPartialWhileBackgroundTaskRunning.js | copyFileToTestAppDir - [copyFileToTestAppDir : 2626] the file or directory should exist, leafName: application.ini - true == true
[task 2024-01-31T08:11:28.285Z] 08:11:28     INFO -  TEST-PASS | toolkit/mozapps/update/tests/unit_base_updater/marSuccessPartialWhileBackgroundTaskRunning.js | copyFileToTestAppDir - [copyFileToTestAppDir : 2626] the file or directory should exist, leafName: dependentlibs.list - true == true
[task 2024-01-31T08:11:28.285Z] 08:11:28     INFO -  TEST-PASS | toolkit/mozapps/update/tests/unit_base_updater/marSuccessPartialWhileBackgroundTaskRunning.js | copyFileToTestAppDir - [copyFileToTestAppDir : 2626] the file or directory should exist, leafName: omni.ja - true == true
[task 2024-01-31T08:11:28.285Z] 08:11:28     INFO -  TEST-PASS | toolkit/mozapps/update/tests/unit_base_updater/marSuccessPartialWhileBackgroundTaskRunning.js | copyFileToTestAppDir - [copyFileToTestAppDir : 2626] the file or directory should exist, leafName: omni.ja - true == true
[task 2024-01-31T08:11:28.285Z] 08:11:28     INFO -  TEST-PASS | toolkit/mozapps/update/tests/unit_base_updater/marSuccessPartialWhileBackgroundTaskRunning.js | copyFileToTestAppDir - [copyFileToTestAppDir : 2626] the file or directory should exist, leafName: XUL - true == true
[task 2024-01-31T08:11:28.285Z] 08:11:28     INFO -  TEST-PASS | toolkit/mozapps/update/tests/unit_base_updater/marSuccessPartialWhileBackgroundTaskRunning.js | copyFileToTestAppDir - [copyFileToTestAppDir : 2673] XUL should be a symlink - true == true
[task 2024-01-31T08:11:28.285Z] 08:11:28     INFO -  "08:11:28:217 | TEST-INFO | xpcshellUtilsAUS.js | [setupAppFiles : 2569] finish - copying or creating symlinks to application files for the test"
[task 2024-01-31T08:11:28.286Z] 08:11:28     INFO -  "08:11:28:217 | TEST-INFO | xpcshellUtilsAUS.js | [setupUpdaterTest : 3263] finish - updater test setup"
[task 2024-01-31T08:11:28.286Z] 08:11:28     INFO -  TEST-PASS | toolkit/mozapps/update/tests/unit_base_updater/marSuccessPartialWhileBackgroundTaskRunning.js | do_backgroundtask - [do_backgroundtask : 52] resource://testing-common is not substituted - true == true
[task 2024-01-31T08:11:28.286Z] 08:11:28     INFO -  PID 4546 | console.info: "launching background task" ({command:"/opt/worker/tasks/task_170668836657033/build/tests/xpcshell/tests/toolkit/mozapps/update/tests/unit_base_updater/marSuccessPartialWhileBackgroundTaskRunning/dir.app/Contents/MacOS/firefox", args:["--backgroundtask", "file_exists", "/opt/worker/tasks/task_170668836657033/build/tests/xpcshell/tests/toolkit/mozapps/update/tests/unit_base_updater/marSuccessPartialWhileBackgroundTaskRunning/dir.app/Contents/Resources/0/00/00text2"], extraEnv:{XPCSHELL_TESTING_MODULES_URI:"file:///opt/worker/tasks/task_170668836657033/build/tests/modules/"}})
[task 2024-01-31T08:11:28.286Z] 08:11:28  WARNING -  TEST-UNEXPECTED-FAIL | toolkit/mozapps/update/tests/unit_base_updater/marSuccessPartialWhileBackgroundTaskRunning.js | run_test - [run_test : 74] 11 == -9
[task 2024-01-31T08:11:28.286Z] 08:11:28     INFO -  /opt/worker/tasks/task_170668836657033/build/tests/xpcshell/tests/toolkit/mozapps/update/tests/unit_base_updater/marSuccessPartialWhileBackgroundTaskRunning.js:run_test:74
[task 2024-01-31T08:11:28.286Z] 08:11:28     INFO -  /opt/worker/tasks/task_170668836657033/build/tests/xpcshell/head.js:_do_main:245
[task 2024-01-31T08:11:28.286Z] 08:11:28     INFO -  /opt/worker/tasks/task_170668836657033/build/tests/xpcshell/head.js:_execute_test:596
[task 2024-01-31T08:11:28.286Z] 08:11:28     INFO -  -e:null:1
[task 2024-01-31T08:11:28.286Z] 08:11:28     INFO -  exiting test
[task 2024-01-31T08:11:28.286Z] 08:11:28     INFO -  PID 4546 | JavaScript error: /opt/worker/tasks/task_170668836657033/build/tests/xpcshell/head.js, line 869: NS_ERROR_ABORT
[task 2024-01-31T08:11:28.286Z] 08:11:28     INFO -  "CONSOLE_MESSAGE: (error) [JavaScript Error: "NS_ERROR_ABORT" {file: "/opt/worker/tasks/task_170668836657033/build/tests/xpcshell/head.js" line: 869}]"
[task 2024-01-31T08:11:28.287Z] 08:11:28  WARNING -  TEST-UNEXPECTED-FAIL | toolkit/mozapps/update/tests/unit_base_updater/marSuccessPartialWhileBackgroundTaskRunning.js | assertNoUncaughtRejections - [assertNoUncaughtRejections : 266] A promise chain failed to handle a rejection: [Exception... "Abort"  nsresult: "0x80004004 (NS_ERROR_ABORT)"  location: "JS frame :: /opt/worker/tasks/task_170668836657033/build/tests/xpcshell/head.js :: _abort_failed_test :: line 869"  data: no] - stack: _abort_failed_test@/opt/worker/tasks/task_170668836657033/build/tests/xpcshell/head.js:869:20
[task 2024-01-31T08:11:28.287Z] 08:11:28     INFO -  do_report_result@/opt/worker/tasks/task_170668836657033/build/tests/xpcshell/head.js:981:5
[task 2024-01-31T08:11:28.287Z] 08:11:28     INFO -  Assert<@/opt/worker/tasks/task_170668836657033/build/tests/xpcshell/head.js:70:21
[task 2024-01-31T08:11:28.287Z] 08:11:28     INFO -  Assert.prototype.report@resource://testing-common/Assert.sys.mjs:258:10
[task 2024-01-31T08:11:28.287Z] 08:11:28     INFO -  equal@resource://testing-common/Assert.sys.mjs:300:8
[task 2024-01-31T08:11:28.287Z] 08:11:28     INFO -  run_test@/opt/worker/tasks/task_170668836657033/build/tests/xpcshell/tests/toolkit/mozapps/update/tests/unit_base_updater/marSuccessPartialWhileBackgroundTaskRunning.js:74:10
[task 2024-01-31T08:11:28.287Z] 08:11:28     INFO -  _do_main@/opt/worker/tasks/task_170668836657033/build/tests/xpcshell/head.js:245:6
[task 2024-01-31T08:11:28.287Z] 08:11:28     INFO -  _execute_test@/opt/worker/tasks/task_170668836657033/build/tests/xpcshell/head.js:596:5
[task 2024-01-31T08:11:28.287Z] 08:11:28     INFO -  @-e:1:1
[task 2024-01-31T08:11:28.287Z] 08:11:28     INFO -  Rejection date: Wed Jan 31 2024 08:11:28 GMT+0000 (Greenwich Mean Time) - false == true
[task 2024-01-31T08:11:28.287Z] 08:11:28     INFO -  resource://testing-common/PromiseTestUtils.sys.mjs:assertNoUncaughtRejections:266
[task 2024-01-31T08:11:28.287Z] 08:11:28     INFO -  /opt/worker/tasks/task_170668836657033/build/tests/xpcshell/head.js:_execute_test:597
[task 2024-01-31T08:11:28.287Z] 08:11:28     INFO -  -e:null:1
[task 2024-01-31T08:11:28.287Z] 08:11:28     INFO -  exiting test
[task 2024-01-31T08:11:28.287Z] 08:11:28     INFO -  "08:11:28:256 | TEST-INFO | xpcshellUtilsAUS.js | [AGP_cleanup : 4523] start - unregistering directory provider"
[task 2024-01-31T08:11:28.287Z] 08:11:28     INFO -  "08:11:28:256 | TEST-INFO | xpcshellUtilsAUS.js | [cleanupTestCommon : 990] start - general test cleanup"
[task 2024-01-31T08:11:28.287Z] 08:11:28     INFO -  "08:11:28:256 | TEST-INFO | xpcshellUtilsAUS.js | [cleanupTestCommon : 1099] attempting to remove directory. Path: /opt/worker/tasks/task_170668836657033/build/tests/xpcshell/tests/toolkit/mozapps/update/tests/unit_base_updater/marSuccessPartialWhileBackgroundTaskRunning"
[task 2024-01-31T08:11:28.288Z] 08:11:28     INFO -  "08:11:28:256 | TEST-INFO | shared.js | [removeDirRecursive : 601] attempting to remove directory. Path: /opt/worker/tasks/task_170668836657033/build/tests/xpcshell/tests/toolkit/mozapps/update/tests/unit_base_updater/marSuccessPartialWhileBackgroundTaskRunning"
[task 2024-01-31T08:11:28.288Z] 08:11:28     INFO -  "08:11:28:261 | TEST-INFO | xpcshellUtilsAUS.js | [cleanupTestCommon : 1115] finish - general test cleanup"
[task 2024-01-31T08:11:28.288Z] 08:11:28     INFO -  "08:11:28:261 | TEST-INFO | xpcshellUtilsAUS.js | [AGP_cleanup : 4587] finish - unregistering directory provider"
[task 2024-01-31T08:11:28.288Z] 08:11:28     INFO -  <<<<<<<
[task 2024-01-31T08:11:28.288Z] 08:11:28     INFO -  TEST-START | toolkit/mozapps/update/tests/unit_base_updater/marAppApplyUpdateStageSuccess.js

Hi Nick! Can you please take a look at this?
Thank you!

Flags: needinfo?(nalexander)

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

status-firefox122: --- → unaffected
status-firefox123: --- → unaffected
status-firefox124: --- → affected
status-firefox-esr115: --- → unaffected

This is so strange: the tests are passing on autoland; for example, here's the green test-macosx1100-64-shippable-qr/opt-xpcshell-spi-nw-1. And inspecting the log of that job clearly shows it passing the relevant tests:

...
[task 2024-01-30T21:06:38.595Z] 21:06:38     INFO -  TEST-START | toolkit/mozapps/update/tests/unit_base_updater/marSuccessPartial.js
[task 2024-01-30T21:06:38.619Z] 21:06:38     INFO -  TEST-PASS | toolkit/mozapps/update/tests/unit_base_updater/marMissingUpdateSettingsStage.js | took 1159ms
[task 2024-01-30T21:06:38.625Z] 21:06:38     INFO -  TEST-START | toolkit/mozapps/update/tests/unit_base_updater/marSuccessPartialWhileBackgroundTaskRunning.js
[task 2024-01-30T21:06:39.042Z] 21:06:39     INFO -  TEST-PASS | toolkit/mozapps/update/tests/unit_base_updater/marAppInUseStageSuccessComplete_unix.js | took 2610ms
[task 2024-01-30T21:06:39.050Z] 21:06:39     INFO -  TEST-START | toolkit/mozapps/update/tests/unit_base_updater/marVersionDowngrade.js
[task 2024-01-30T21:06:39.493Z] 21:06:39     INFO -  TEST-PASS | toolkit/mozapps/update/tests/unit_base_updater/marAppApplyUpdateStageSuccess.js | took 3434ms
...

(Everything passed on try as well: see this job for example.)

Current theory is that we're seeing macOS signing/notarization differences between m-c and autoland; I've requested a backout of the regressing ticket in #developers on Matrix.

Flags: needinfo?(nalexander)

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit BugBot documentation.

Status: NEW → RESOLVED
Closed: 9 months ago
status-firefox124: affected → wontfix
Resolution: --- → INCOMPLETE
See Also: → 1919455
You need to log in before you can comment on or make changes to this bug.