Open Bug 1760099 Opened 4 years ago Updated 21 hours ago

Frequent toolkit/mozapps/update/tests/unit_background_update/test_backgroundupdate_exitcodes.js | single tracking bug

Categories

(Toolkit :: Application Update, defect, P3)

Product:
Toolkit
Component:
Application Update
Type:
defect

Tracking

()

Status:
REOPENED
Tracking Flags:
Tracking Status
firefox153 --- affected
firefox154 --- affected

People

(Reporter: jmaher, Unassigned)

References

(Depends on 1 open bug)

Details

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

Attachments

(7 files, 1 obsolete file)

Bug 1760099: Log processes holding updater lock in test_backgroundupdate_exitcodes.js on Windows r=#win-reviewers!
48 bytes, text/x-phabricator-request
Details | Review
Bug 1760099: Fix service name in test_backgroundupdate_exitcodes r=#win-reviewers!
48 bytes, text/x-phabricator-request
Details | Review
Bug 1760099 - Retry the exclusive lock check before reporting another running instance on Windows, r=#win-reviewers.
48 bytes, text/x-phabricator-request
Details | Review
Bug 1760099 - Skip test_backgroundupdate_exitcodes.js on Windows x86_64 opt with the profiler enabled by default, r=nalexander.
48 bytes, text/x-phabricator-request
Details | Review
Dump of the locked process
251.01 KB, application/json
Details
WIP: Bug 1760099 - Use the correct lock file path in debug output. r=#win-reviewers!
48 bytes, text/x-phabricator-request
Details | Review
Bug 1760099 - Don't use the default update lock in crash reporter tests. r=gsvelto
48 bytes, text/x-phabricator-request
Details | Review
No description provided.
Severity: -- → S3

Update:

There have been 40 failures within the last 7 days:

  • 18 failures on Windows 7 WebRender opt
  • 22 failures on Windows 7 WebRender Shippable opt

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=403088355&repo=autoland&lineNumber=4446

[task 2023-01-21T06:15:22.389Z] 06:15:22     INFO -  TEST-START | toolkit/mozapps/update/tests/unit_background_update/test_backgroundupdate_exitcodes.js
[task 2023-01-21T06:15:22.566Z] 06:15:22     INFO -  Failed to remove directory: C:\Users\task_1674279689\AppData\Local\Temp\xpc-other-8m2tmoej. Waiting.
[task 2023-01-21T06:15:22.789Z] 06:15:22  WARNING -  TEST-UNEXPECTED-FAIL | toolkit/mozapps/update/tests/unit_background_update/test_backgroundupdate_exitcodes.js | xpcshell return code: 0
[task 2023-01-21T06:15:22.789Z] 06:15:22     INFO -  TEST-INFO took 399ms
[task 2023-01-21T06:15:22.789Z] 06:15:22     INFO -  >>>>>>>
[task 2023-01-21T06:15:22.790Z] 06:15:22     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2023-01-21T06:15:22.790Z] 06:15:22     INFO -  (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2023-01-21T06:15:22.790Z] 06:15:22     INFO -  (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2023-01-21T06:15:22.791Z] 06:15:22     INFO -  running event loop
[task 2023-01-21T06:15:22.791Z] 06:15:22     INFO -  toolkit/mozapps/update/tests/unit_background_update/test_backgroundupdate_exitcodes.js | Starting test_default_profile_does_not_exist
[task 2023-01-21T06:15:22.791Z] 06:15:22     INFO -  (xpcshell/head.js) | test test_default_profile_does_not_exist pending (2)
[task 2023-01-21T06:15:22.792Z] 06:15:22     INFO -  TEST-PASS | toolkit/mozapps/update/tests/unit_background_update/test_backgroundupdate_exitcodes.js | test_default_profile_does_not_exist - [test_default_profile_does_not_exist : 52] resource://testing-common is not substituted - true == true
[task 2023-01-21T06:15:22.792Z] 06:15:22     INFO -  PID 5776 | console.info: "launching background task" ({command:"Z:\\\\task_1674279689\\\\build\\\\application\\\\firefox\\\\firefox.exe", args:["--backgroundtask", "backgroundupdate"], extraEnv:{MOZ_BACKGROUNDTASKS_NO_DEFAULT_PROFILE:"1", XPCSHELL_TESTING_MODULES_URI:"file:///Z:/task_1674279689/build/tests/modules/"}})
[task 2023-01-21T06:15:22.793Z] 06:15:22     INFO -  (xpcshell/head.js) | test run_next_test 0 finished (2)
[task 2023-01-21T06:15:22.793Z] 06:15:22     INFO -  PID 5776 | 4648> *** You are running in background task mode. ***
[task 2023-01-21T06:15:22.793Z] 06:15:22     INFO -  PID 5776 | 4648> *** You are running in headless mode.
[task 2023-01-21T06:15:22.794Z] 06:15:22     INFO -  PID 5776 | 4648> console.error: BackgroundTasksManager:
[task 2023-01-21T06:15:22.794Z] 06:15:22     INFO -  PID 5776 | 4648>   Substitution set: resource://testing-common aliases file:///Z:/task_1674279689/build/tests/modules/
[task 2023-01-21T06:15:22.794Z] 06:15:22     INFO -  PID 5776 | 4648> console.error: BackgroundUpdate:
[task 2023-01-21T06:15:22.795Z] 06:15:22     INFO -  PID 5776 | 4648>   runBackgroundTask: backgroundupdate
[task 2023-01-21T06:15:22.795Z] 06:15:22     INFO -  PID 5776 | 4648> console.error: BackgroundUpdate:
[task 2023-01-21T06:15:22.795Z] 06:15:22     INFO -  PID 5776 | 4648>   runBackgroundTask: another instance is running
[task 2023-01-21T06:15:22.796Z] 06:15:22  WARNING -  TEST-UNEXPECTED-FAIL | toolkit/mozapps/update/tests/unit_background_update/test_backgroundupdate_exitcodes.js | test_default_profile_does_not_exist - [test_default_profile_does_not_exist : 34] 11 == 21
[task 2023-01-21T06:15:22.796Z] 06:15:22     INFO -  Z:/task_1674279689/build/tests/xpcshell/tests/toolkit/mozapps/update/tests/unit_background_update/test_backgroundupdate_exitcodes.js:test_default_profile_does_not_exist:34
[task 2023-01-21T06:15:22.797Z] 06:15:22     INFO -  Z:\task_1674279689\build\tests\xpcshell\head.js:_do_main:238
[task 2023-01-21T06:15:22.797Z] 06:15:22     INFO -  Z:\task_1674279689\build\tests\xpcshell\head.js:_execute_test:585
[task 2023-01-21T06:15:22.797Z] 06:15:22     INFO -  -e:null:1
[task 2023-01-21T06:15:22.797Z] 06:15:22     INFO -  exiting test
[task 2023-01-21T06:15:22.798Z] 06:15:22     INFO -  Unexpected exception NS_ERROR_ABORT:
[task 2023-01-21T06:15:22.798Z] 06:15:22     INFO -  _abort_failed_test@Z:\task_1674279689\build\tests\xpcshell\head.js:863:20
[task 2023-01-21T06:15:22.798Z] 06:15:22     INFO -  do_report_result@Z:\task_1674279689\build\tests\xpcshell\head.js:964:5
[task 2023-01-21T06:15:22.799Z] 06:15:22     INFO -  Assert<@Z:\task_1674279689\build\tests\xpcshell\head.js:71:21
[task 2023-01-21T06:15:22.799Z] 06:15:22     INFO -  Assert.prototype.report@resource://testing-common/Assert.sys.mjs:240:10
[task 2023-01-21T06:15:22.799Z] 06:15:22     INFO -  equal@resource://testing-common/Assert.sys.mjs:282:8
[task 2023-01-21T06:15:22.800Z] 06:15:22     INFO -  test_default_profile_does_not_exist@Z:/task_1674279689/build/tests/xpcshell/tests/toolkit/mozapps/update/tests/unit_background_update/test_backgroundupdate_exitcodes.js:34:10
[task 2023-01-21T06:15:22.800Z] 06:15:22     INFO -  _do_main@Z:\task_1674279689\build\tests\xpcshell\head.js:238:6
[task 2023-01-21T06:15:22.801Z] 06:15:22     INFO -  _execute_test@Z:\task_1674279689\build\tests\xpcshell\head.js:585:5
[task 2023-01-21T06:15:22.801Z] 06:15:22     INFO -  @-e:1:1
[task 2023-01-21T06:15:22.801Z] 06:15:22     INFO -  exiting test

Nick, as the owner of this component, can you help us assign the bug to someone?
Thank you.

Flags: needinfo?(nrishel)
test_default_profile_does_not_exist - [test_default_profile_does_not_exist : 34] 11 == 21

BackgroundUpdate.EXIT_CODE = {
...
  // Another instance is running.
  OTHER_INSTANCE: 21,
};

:nalexander looks like a preceding test overrunning into this one causing this one to fail?

Flags: needinfo?(nrishel) → needinfo?(nalexander)

(In reply to Nick Rishel [:nrishel] from comment #16)

test_default_profile_does_not_exist - [test_default_profile_does_not_exist : 34] 11 == 21

BackgroundUpdate.EXIT_CODE = {
...
  // Another instance is running.
  OTHER_INSTANCE: 21,
};

:nalexander looks like a preceding test overrunning into this one causing this one to fail?

Yes, exactly. The issue is that xpcshell instances take the multi-process mutex, which causes the firefox --backgroundtask backgroundupdate invocation to bail. Inspecting a few of these failure runs, I see crash reporter tests timing out and evidence that those test processes remain:

[task 2023-01-23T21:44:40.138Z] 21:44:40     INFO -  rmtree() failed for "('\\\\?\\C:\\Users\\task_1674508474\\AppData\\Local\\Temp\\xpc-other-twkxpgoy',)". Reason: The process cannot access the file because it is being used by another process (13). Retrying...

So when the backgroundupdate task comes along, it fails because the lock is (legitimately) taken. We could avoid that by changing the background update lock behaviour while under test, but I'm loathe to do that: it makes it harder to reason about and test the behaviour we actually ship.

I notice that these test failures are mostly on Windows 7. Is it possible we just need to give the crash reporter tests longer timeouts on what might be older hardware? I don't know if we have data which would give us descriptive statistics on the runtime of the crash reporter tests on different hardware. Maybe jmaher could help us understand that question?

Ultimately, I strongly believe that this is another test failing and that test and the test harness not cleaning up correctly, and not the background update test itself.

Flags: needinfo?(nalexander) → needinfo?(jmaher)

win7 is a different beast- we are the only browser that supports win7, and we are looking to reduce our test coverage on win7.

can we run these tests sequentially, and not in parallel? It might be as easy as doing that, it is done for a lot of tests already:
https://searchfox.org/mozilla-central/search?q=run-sequentially&path=&case=false&regexp=false

It is very possible that we have bleedthrough from another test - parallel runs only add to that; we should have profile separation, but I am not sure about system wide events, etc.

Flags: needinfo?(jmaher)

(In reply to Joel Maher ( :jmaher ) (UTC -8) from comment #18)

win7 is a different beast- we are the only browser that supports win7, and we are looking to reduce our test coverage on win7.

can we run these tests sequentially, and not in parallel? It might be as easy as doing that, it is done for a lot of tests already:
https://searchfox.org/mozilla-central/search?q=run-sequentially&path=&case=false&regexp=false

Yes, and this test is labeled run-sequentially (which doesn't seem to be working), but it doesn't prevent the "bleedthrough" you suggest below.

It is very possible that we have bleedthrough from another test - parallel runs only add to that; we should have profile separation, but I am not sure about system wide events, etc.

Hence investigating timeouts...

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

Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → INCOMPLETE

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=421143623&repo=autoland

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

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

Status: REOPENED → RESOLVED
Closed: 3 years ago → 2 years ago
Resolution: --- → INCOMPLETE

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=431201543&repo=autoland

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Attachment #9384507 - Attachment is obsolete: true

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

Status: REOPENED → RESOLVED
Closed: 2 years ago → 2 years ago
Resolution: --- → INCOMPLETE

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=452051877&repo=autoland

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

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

Status: REOPENED → RESOLVED
Closed: 2 years ago → 2 years ago
Resolution: --- → INCOMPLETE

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=460119956&repo=mozilla-beta

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

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

Status: REOPENED → RESOLVED
Closed: 2 years ago → 2 years ago
Resolution: --- → INCOMPLETE

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=471079847&repo=mozilla-esr128

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

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

Status: REOPENED → RESOLVED
Closed: 2 years ago → 1 year ago
Resolution: --- → INCOMPLETE

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=475395125&repo=autoland

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

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

Status: REOPENED → RESOLVED
Closed: 1 year ago → 1 year ago
Resolution: --- → INCOMPLETE

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=486932879&repo=try

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

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

Status: REOPENED → RESOLVED
Closed: 1 year ago → 1 year ago
Resolution: --- → INCOMPLETE

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=525600823&repo=autoland

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

Hi! This has a high frequency on windows. Can you please take a look?

Flags: needinfo?(mpohle)

(In reply to Silaghi Andreea from comment #123)

Hi! This has a high frequency on windows. Can you please take a look?

It's pretty hard to understand what could be driving these intermittents; we literally launch a process and wait for it to die, checking the exit code. We might be hitting some kind of Windows-specific file locking... that's what I'd start with. We could try to make the test more robust by doing it a few times (say 3 or 5).

is anyone looking into this?

Summary: Intermittent toolkit/mozapps/update/tests/unit_background_update/test_backgroundupdate_exitcodes.js | single tracking bug → Frequent toolkit/mozapps/update/tests/unit_background_update/test_backgroundupdate_exitcodes.js | single tracking bug

(In reply to Nick Alexander :nalexander [he/him] from comment #124)

(In reply to Silaghi Andreea from comment #123)

Hi! This has a high frequency on windows. Can you please take a look?

It's pretty hard to understand what could be driving these intermittents; we literally launch a process and wait for it to die, checking the exit code. We might be hitting some kind of Windows-specific file locking... that's what I'd start with. We could try to make the test more robust by doing it a few times (say 3 or 5).

Retrying is likely a good call, but I think the root cause may be in production code, not the test. On Windows, mozilla::IsOtherInstanceRunning (toolkit/xre/MultiInstanceLock.cpp) does roughly:

  1. Release our own shared lock.
  2. LockFileEx(LOCKFILE_EXCLUSIVE_LOCK | LOCKFILE_FAIL_IMMEDIATELY).
  3. If GetLastError() == ERROR_LOCK_VIOLATION, report "another instance".
  4. Re-acquire shared.

Any other process briefly holding a shared handle on C:\ProgramData\Mozilla-...\UpdateLock-<hash> in the microsecond window of step 2 makes step 3 fire as a false positive. The lock file is created with OPEN_ALWAYS at bgtask startup, which is exactly the kind of just-created file that AV/Defender/Search Indexer/EDR would like to open for scanning. Potential implication: real users running Defender (essentially every Windows install) may intermittently get their background update bailing silently with OTHER_INSTANCE for the same reason.

It is probably worth retrying LockFileEx(EXCLUSIVE | FAIL_IMMEDIATELY) a few times with a short backoff in IsOtherInstanceRunning before concluding "another instance is running" ?

Both comment 17 and comment 156 seem like potential culprits here. FWIW, we do still have very occasional MacOS failures that show the same behavior. The patterns of when this failed and on what platform are bizarre. This could be something about our environment that isn't common in practice.

I've tried to collect the names of the processes holding the lock but I'm not seeing the failure so it's still TBD. I think that can be cleaned up and added to the log message so the log tells us what is causing this (on Windows anyway).

This should help us pin down the occasional failures in automation.

Assignee: nobody → davidp99

@cdupuis has a better idea of what is going on here:

This is how the test is trying to make the default profile appear to not exist:

// Pretend there's no default profile.
  let exitCode = await do_backgroundtask("backgroundupdate", {
    extraEnv: {
      MOZ_BACKGROUNDTASKS_NO_DEFAULT_PROFILE: "1",
    },
  });

In the call stack for running, do_backgroundtask..., there is a call to BackgroundTasksUtils.getDefaultProfile
If this method was not called previously in the current process, it works as expected.
But a second call of getDefaultProfile in the same process with different extraEnv will not work as expected.

  if (!this._defaultProfileInitialized) {
      this._defaultProfileInitialized = true;
      // This is all test-only.
      let defaultProfilePath = Services.env.get(
        "MOZ_BACKGROUNDTASKS_DEFAULT_PROFILE_PATH"
      );
      let noDefaultProfile = Services.env.get(
        "MOZ_BACKGROUNDTASKS_NO_DEFAULT_PROFILE"
      );

Because we only look at the environment variables once per process, when this._defaultProfileInitialized is false.
Here's the link to the place: https://searchfox.org/firefox-main/source/toolkit/components/backgroundtasks/BackgroundTasksUtils.sys.mjs#48-88

Pushed by daparks@mozilla.com: https://github.com/mozilla-firefox/firefox/commit/22bbcae771d9 https://hg.mozilla.org/integration/autoland/rev/7b6cccd2bbc4 Log processes holding updater lock in test_backgroundupdate_exitcodes.js on Windows r=win-reviewers,application-update-reviewers,gstoll,cdupuis

https://hg.mozilla.org/mozilla-central/rev/7b6cccd2bbc4

Status: REOPENED → RESOLVED
Closed: 1 year ago → 2 months ago
status-firefox153: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → 153 Branch

I think that patch was just for debugging(?). Marking leave-open so it can be closed once the root cause is found.

Status: RESOLVED → REOPENED
Keywords: leave-open
Resolution: FIXED → ---
Duplicate of this bug: 2041071
Pushed by daparks@mozilla.com: https://github.com/mozilla-firefox/firefox/commit/cb2d7e0bde03 https://hg.mozilla.org/integration/autoland/rev/0efea3e87d17 Fix service name in test_backgroundupdate_exitcodes r=win-reviewers,application-update-reviewers,nalexander,gstoll
Duplicate of this bug: 2044080
Pushed by fqueze@mozilla.com: https://github.com/mozilla-firefox/firefox/commit/479a08f25e0a https://hg.mozilla.org/integration/autoland/rev/22fe9ce0c278 Retry the exclusive lock check before reporting another running instance on Windows, r=win-reviewers,gstoll.
Pushed by agoloman@mozilla.com: https://github.com/mozilla-firefox/firefox/commit/c61623bff309 https://hg.mozilla.org/mozilla-central/rev/8ef1c5b6b940 Retry the exclusive lock check before reporting another running instance on Windows, r=win-reviewers,gstoll.
Whiteboard: [stockwell disable-recommended]

For context on comment 197, this test becomes an almost perma fail when I push to try the patches from bug 2032957 that enable profiling xpcshell tests by default.

In #desktop-integrations, Nick told me:

skipping it would be totally fine.  This test is pretty low value; it’s just making sure that background update tasks return with the correct error codes.  I’m not even sure anything uses those codes (beyond the Task Scheduler reporting success/error).

Pushed by fqueze@mozilla.com: https://github.com/mozilla-firefox/firefox/commit/c692116249d7 https://hg.mozilla.org/integration/autoland/rev/0d033a5fd9c3 Skip test_backgroundupdate_exitcodes.js on Windows x86_64 opt with the profiler enabled by default, r=nalexander,application-update-reviewers.

(note: comment written by an Agent)

What's going on: the "OTHER_INSTANCE" failures are caused by intentionally-crashed crashreporter test children that hang in MiniDumpWriteDump and never exit, holding the update lock

test_backgroundupdate_exitcodes.js is the victim, not the culprit: it intermittently fails with OTHER_INSTANCE (21) instead of DEFAULT_PROFILE_DOES_NOT_EXIST (11) because, at the moment it launches the background task, some other main-process xpcshell.exe is still alive and holding the install-dir update lock (UpdateLock-<hash>).

That lingering process is an intentionally-crashed child spawned by a toolkit/crashreporter/test/unit/ test (via do_crash(), which launches xpcshell -g GreD -f head -e <setup> -f tail and crashes it). The child crashes as expected, but then hangs forever while writing its own minidump, so it never releases the lock. Spawning tests seen wedged across four CI jobs in one try push:

  • toolkit/crashreporter/test/unit/test_crash_modules.js
  • toolkit/crashreporter/test/unit/test_crash_after_js_oom_reported.js (twice)
  • toolkit/crashreporter/test/unit/test_crash_purevirtual.js
  • toolkit/crashreporter/test/unit/test_crash_win64cfi_save_nonvol_far.js

So it's not a specific test — any crashreporter do_crash test can leave a wedged child; test_backgroundupdate_exitcodes.js just happens to be the one that notices.

Root cause (deadlock in the in-process minidump writer)

Captured full minidumps of five wedged holders from four different jobs. Every one has the identical stack on its breakpad handler thread (fully symbolized, all-CFI / reliable):

ntdll!NtWaitForSingleObject
ntdll!LdrpDrainWorkQueue
ntdll!LdrpLoadDllInternal
ntdll!LdrpLoadDll
ntdll!LdrLoadDll
mozglue!patched_LdrLoadDll               // DLL-blocklist hook (pass-through here)
KERNELBASE!LoadLibraryExW
KERNELBASE!LoadLibraryExA
dbgcore!Win32LiveSystemProvider::StartHandleOperationsEnum
dbgcore!GenWriteHandleOperations          // writing the handle-data stream
dbgcore!WriteDumpData
dbgcore!MiniDumpProvideDump
dbgcore!MiniDumpWriteDump
xul!google_breakpad::ExceptionHandler::WriteMinidumpWithExceptionForProcess
xul!google_breakpad::ExceptionHandler::WriteMinidumpWithException
xul!google_breakpad::ExceptionHandler::ExceptionHandlerThreadMain

MiniDumpWriteDump suspends every other thread in the process, then — while writing the handle-data stream (MiniDumpWithHandleData, which is in our minidump type) — calls LoadLibrary. On Win10+ LdrLoadDll blocks in LdrpDrainWorkQueue waiting for the parallel-loader work queue to drain, but the loader worker thread(s) that would drain it were just suspended by MiniDumpWriteDump. Nobody drains the queue → the load never returns → the dump never finishes → the process never exits → the update lock is held until the worker is reaped (minutes later), long enough for exitcodes to see OTHER_INSTANCE. This is the classic "don't LoadLibrary while you've suspended threads the loader needs," hit from inside MiniDumpWriteDump itself. It's Windows-only because this is the in-process self-dump path (Linux/macOS dump differently). The mozglue!patched_LdrLoadDll (DLL-blocklist) frame is just a pass-through; the wait is in the real loader.

How the minidumps were obtained

The hung process's own dump is exactly what's broken, so we dumped it from outside. A WIP diagnostic in test_backgroundupdate_exitcodes.js, on seeing OTHER_INSTANCE, enumerates the processes holding the real install-dir lock and for each one does NtSuspendProcess + dbghelp!MiniDumpWriteDump (full memory) into MOZ_UPLOAD_DIR. (Dumping the hung process externally works fine — only the in-process dump deadlocks.) Symbolized with the try build's target.crashreporter-symbols-full plus --symbols-url=https://symbols.mozilla.org/ for the system DLLs. Attaching the processed minidump-stackwalk JSON for one holder.

Suggestions to move forward

  1. Generate the minidump out-of-process (via the crash helper) instead of in-process for the main process on Windows. The external dumps above prove dumping this process from another process succeeds — the deadlock only happens when the dumping thread lives in the same process whose loader threads it suspended. This is the robust fix and matches where child-process crash handling already is.
  2. Cheaper interim / causation check: stop pulling a LoadLibrary into the dump path — drop MiniDumpWithHandleData from the minidump type (or pre-load whatever StartHandleOperationsEnum needs before suspending threads). A try push with MiniDumpWithHandleData removed should make the holders stop wedging, confirming the mechanism.

drop MiniDumpWithHandleData from the minidump type. A try push with MiniDumpWithHandleData removed should make the holders stop wedging, confirming the mechanism.

Try just confirmed that removing the MiniDumpWithHandleData flag indeed makes the failures disappear: https://treeherder.mozilla.org/jobs?repo=try&revision=76d7f60a13c68192ef6302eb68daa87303921244

Pushed by rperta@mozilla.com: https://github.com/mozilla-firefox/firefox/commit/37537a5ba7e1 https://hg.mozilla.org/integration/autoland/rev/0cfa153e1ca4 Revert "Bug 1760099, Bug 2032957 - Skip test_backgroundupdate_exitcodes.js on Windows x86_64 opt with the profiler enabled by default, r=nalexander,application-update-reviewers." for causing xpc failures at test_search_suggestions.js

Backed out for causing xpc failures at test_search_suggestions.js
Backout link
Push with failures
Failure log(s)

Flags: needinfo?(davidp99)
Pushed by rperta@mozilla.com: https://github.com/mozilla-firefox/firefox/commit/10effc7fd9aa https://hg.mozilla.org/integration/autoland/rev/871dc7d39191 Skip test_backgroundupdate_exitcodes.js on Windows x86_64 opt with the profiler enabled by default, r=nalexander,application-update-reviewers.
Depends on: 2050963

Conclusion of my investigations:

The recent Windows spike is from enabling the profiler by default for xpcshell tests; that's being addressed in bug 2050963.

This test is a victim: it sees OTHER_INSTANCE because a crashed do_crash() child from a toolkit/crashreporter/test/unit/ test hangs in its own in-process MiniDumpWriteDump (suspends all threads, then LoadLibrary deadlocks on a loader lock a suspended thread holds) and never releases the update lock.

Bug 2050963 fixes the dominant trigger (the verifier.dll load from MiniDumpWithHandleData). A residual ~2/40 remains from the same class via a different, non-flag-gated LoadLibrary site. Example from a symbolicated holder:

KERNELBASE!LoadLibraryExW
dbgcore!Win32LiveSystemProvider::CheckForAuxProvider
dbgcore!GenAddAuxProvider
dbgcore!GenGetProcessInfo
dbgcore!MiniDumpWriteDump

stuck on an ntdll env/DLL-path critical section owned (per the dump) by a suspended "Link Monitor #1" thread mid CoCreateInstance(NetworkListManager) -> GetEnvironmentStringsW. The holder is incidental — any thread holding a loader/PEB lock at crash time blocks the dump. Only out-of-process dump generation (bug 587729) closes the whole class.

Depends on: 587729

https://hg.mozilla.org/mozilla-central/rev/871dc7d39191

Status: REOPENED → RESOLVED
Closed: 2 months ago → 1 month ago
status-firefox154: --- → fixed
Resolution: --- → FIXED
Target Milestone: 153 Branch → 154 Branch
Status: RESOLVED → REOPENED
Keywords: leave-open
Resolution: FIXED → ---

Thanks for taking this up, Florian.

Assignee: davidp99 → nobody
Flags: needinfo?(davidp99)
status-firefox154: fixed → affected
Target Milestone: 154 Branch → ---
Flags: needinfo?(mpohle)

Hello,

Are there any updates regarding this? There are almost 400 failures in the last 30 days.
Thanks.

Flags: needinfo?(dmcintosh)

The debug output looks at the lock that the xpcshell process is
currently using, but it specifically moved to a different one to try and
avoid the current locking problem.

I wasn't able to reproduce it in a try run (https://treeherder.mozilla.org/jobs?repo=try&revision=5da46fef3087ba1020071d77c50d0ed148d0f00b), so my current bet is to try and get more accurate debug output in the hope it reveals the smoking gun.

Flags: needinfo?(dmcintosh)

(In reply to Duncan McIntosh [:dmcintosh] from comment #224)

I wasn't able to reproduce it in a try run (https://treeherder.mozilla.org/jobs?repo=try&revision=5da46fef3087ba1020071d77c50d0ed148d0f00b), so my current bet is to try and get more accurate debug output in the hope it reveals the smoking gun.

This job of your push reproduced: https://treeherder.mozilla.org/jobs?repo=try&selectedTaskRun=LOxyKGQQTQ-LJU2f1j-INw.0&revision=5da46fef3087ba1020071d77c50d0ed148d0f00b

But there were so many other failures that treeherder can't show it. You can see it on https://tests.firefox.dev/try.html?rev=5da46fef3087ba1020071d77c50d0ed148d0f00b&filter=exit

(In reply to Florian Quèze [:florian] from comment #225)

(In reply to Duncan McIntosh [:dmcintosh] from comment #224)

I wasn't able to reproduce it in a try run (https://treeherder.mozilla.org/jobs?repo=try&revision=5da46fef3087ba1020071d77c50d0ed148d0f00b), so my current bet is to try and get more accurate debug output in the hope it reveals the smoking gun.

This job of your push reproduced: https://treeherder.mozilla.org/jobs?repo=try&selectedTaskRun=LOxyKGQQTQ-LJU2f1j-INw.0&revision=5da46fef3087ba1020071d77c50d0ed148d0f00b

Ah, thank you! Not used to digging a whole bunch down the list of failures, usually I only look at the top two. Will try poking at this a bit more then.

Flags: needinfo?(dmcintosh)
Attachment #9614503 - Attachment description: Bug 1760099 - Use the correct lock file path in test_backgroundupdate_exitcodes.js debug output. r=#win-reviewers! → WIP: Bug 1760099 - Use the correct lock file path in debug output. r=#win-reviewers!

OK, haven't gotten that much further, but here's what I know:

  • It looks like most recent failures on Windows 11 are firefox-release / firefox-esr153, which makes sense because bug 2050963 (where that issue was supposed to be fixed) isn't there.
  • There's also some leftover failures on Windows 10 even on autoland / firefox-beta.
  • I think we can work around these by having the crashreporter tests take a different update lock, I'll submit a patch shortly that seems to help (doesn't seem to repro anymore in a try run, does seem a little hackish).
  • Some of the failures are on macOS. It looks like these are due to profile downgrades, which seems kind of similar to bug 2007820, but I don't have an explanation for either. I don't know usual intermittent procedure, would it make sense to split that into a different bug?

florian: is bug 2050963 worth uplifting, or too complex? any reason it'd impact Win11 more than Win10?

Flags: needinfo?(dmcintosh) → needinfo?(florian)

In some cases, crash reporter tests can fail by timing out, in which
case the crasher subprocess doesn't die. This means that updater tests
that run later which depend on no other xpcshell instances being present
will fail, since they'll see the existing process and assume that it
isn't safe to update.

Avoid this by using a different update lock (it looks like there has to
be one, so come up with a quick-n-dirty temp name) before crashing.

(In reply to Duncan McIntosh [:dmcintosh] from comment #228)

florian: is bug 2050963 worth uplifting, or too complex?

I think it's upliftable to 153 to reduce the noise on esr. I don't think uplifting to the release channel is useful at this point (but could be convinced otherwise).

any reason it'd impact Win11 more than Win10?

Could the name of the dll we need to preload be different on Win10?

Flags: needinfo?(florian)
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: