Closed Bug 2016440 Opened 7 months ago Closed 1 month ago

Stalled out download of trainhop XPI can still cause shutdown hangs / crashes

Categories

(Firefox :: New Tab Page, defect)

defect

Tracking

()

RESOLVED FIXED
157 Branch
Tracking Status
firefox-esr140 --- unaffected
firefox-esr153 --- wontfix
firefox155 --- wontfix
firefox156 --- fixed
firefox157 --- fixed

People

(Reporter: mconley, Assigned: mconley)

References

(Blocks 2 open bugs)

Details

(Keywords: crash, topcrash)

Crash Data

Attachments

(3 files)

Bug 1991490 addressed a shutdown hang that could occur if a download of the train-hop XPI was occurring but not yet complete at the time of shutdown. From looking at the crash stat graphs over the last few months since that patch landed, and since we've done several more train-hops, it seems that there are still occurances of shutdown hangs occurring:

https://crash-stats.mozilla.org/signature/?signature=AsyncShutdownTimeout%20%7C%20quit-application%20%7C%20newtabTrainhopAddon%20scheduleUpdateTrainhopAddonState%20shutting%20down&date=%3E%3D2025-08-12T14%3A21%3A00.000Z&date=%3C2026-02-12T14%3A21%3A00.000Z#graphs

This bug is for investigating what's going on.

Crash Signature: [@ AsyncShutdownTimeout | quit-application | newtabTrainhopAddon scheduleUpdateTrainhopAddonState shutting down ]

This bug has the keyword crash, so its type should be defect.

Type: task → defect

The severity field is not set for this bug.
:thecount, could you have a look please?

For more information, please visit BugBot documentation.

Flags: needinfo?(sdowne)

One of the things we can perhaps do here is add the fetchState option, to try to give our crash reports a better sense of what state the task is in when it times out.

Before we do that though, I want to back up and consider what happens if we remove the AsyncShutdown blocker altogether. rpl, are we certain that we actually need to finalize an attempt to download / install the train-hop? What is the worst-case scenario for interrupting that process without waiting for it to finish?

Flags: needinfo?(sdowne) → needinfo?(lgreco)

One of the things we can perhaps do here is add the fetchState option, to try to give our crash reports a better sense of what state the task is in when it times out.

That feels valuable, I should have thought about doing that when we were looking into the previous shutdown hang.

Before we do that though, I want to back up and consider what happens if we remove the AsyncShutdown blocker altogether. rpl, are we certain that we actually need to finalize an attempt to download / install the train-hop? What is the worst-case scenario for interrupting that process without waiting for it to finish?

Looking to the logic related to what we are doing inside method that handles the train hop I'd assume nothing too bad should be happening in the most common scenario, I feel that the firstStartup scenario would concern me a bit more because in that case we would be willing to move forward with the staged installation.

To be honest the fact that we do have a deferred task that we are re-arming makes me kind of prefer if we could be sure to finalize it, mainly because it feels odd to leave it without an explicit finalization (but I couldn't think of a particular thing that would make that really bad in practice).

The other thing that was bothering me was not having a more clear idea of what may be going on when the issue is hit and so I took a more close look to the code paths and I tried to force a few more edge cases that I could think of, in particular one where the xpi installation has not been technically started yet by the time we are starting to be shutting down the application, the logic that handles the train hopping has more than a few await for things that are technically async and so it felt like not that unlikely that the shutdown may be initiate in between those async calls being awaited on.

As an example, I managed to hit a shutdown hang consistently by calling Services.startup.quit(Ci.nsIAppStartup.eAttemptQuit) right before the await this._installTrainhopAddon(...) call near the end of the updateTrainhopAddonState here or between that and the install.install() call that gets the installation started.

In that case as you also mentioned briefly in comment 0, the change we have applied as part of Bug 1991490 isn't really helping, with that change we only cancel the installation did actually start to receive some data, but if that wasn't yet the case there wouldn't be any observer in the DownloadAddonInstall instance that would be getting notified about the quit-application-granted topic and so the download would not be cancelled.

The xpcshell test that I'm attaching tries to demonstrate the role that the appShutdownConfirmed shutdown blocker is having in preventing the shutdown to proceed further, and also demonstrates that using profileChangeTeardown doesn't hit that same kind of hang (because that shutdown phase is coming right after the "profile-change-net-teardown" phase where the network teardown does actually make all DownloadAddonInstall to fail due to the onStopRequest http activity triggering the pending download to fail right away (unfortunately I couldn't find a way to test it out as realistically as in the attached patch without calling Services.startup.quit in the test itself, and so I don't consider that test as is something we could land, but I decided to attach it because it demonstrate the same behavior that I was hitting in a Firefox build by forcing an app shutdown purposely at the right time).

Similarly, by applying a change like that in the AboutNewTabResourceMapping.sys.mjs module (as in the diff that follows) I wasn't able to trigger the shutdown hang in the same way as before applying it.

:mconley wdyt? does the following seem worth a try?

(as a side note, the following patch also apply another small tweak to be sure we would not be completed the postponed installation if we got past the download but we are also shutting down).

diff --git a/browser/components/newtab/AboutNewTabResourceMapping.sys.mjs b/browser/components/newtab/AboutNewTabResourceMapping.sys.mjs
index 92f9893f7e15..e66243fe75cd 100644
--- a/browser/components/newtab/AboutNewTabResourceMapping.sys.mjs
+++ b/browser/components/newtab/AboutNewTabResourceMapping.sys.mjs
@@ -399,7 +399,14 @@ export var AboutNewTabResourceMapping = {
         delayMs,
         idleTimeoutMs
       );
-      lazy.AsyncShutdown.appShutdownConfirmed.addBlocker(
+      // Trainhop Updates finalization added as a blocker of AppShutdownTeardown,
+      // which happens right after AppShutdownNetTeardown (which is expected to
+      // stop any DownloadAddonInstall still in progress) and reduce the time needed
+      // by this AsyncShutdown blocker to become fully finalized.
+      //
+      // See https://searchfox.org/firefox-main/rev/ad106dcbb4/ipc/docs/proc_shutdown.md#25-27
+      // for more details about the shutdown sequence.
+      lazy.AsyncShutdown.profileChangeTeardown.addBlocker(
         `${TRAINHOP_NIMBUS_FEATURE_ID} scheduleUpdateTrainhopAddonState shutting down`,
         () => this._updateAddonStateDeferredTask.finalize()
       );
@@ -643,14 +650,20 @@ export var AboutNewTabResourceMapping = {
         },
         onInstallPostponed: () => {
           this.logger.debug("Train-hop install postponed, as expected");
-          if (forceRestartlessInstall && !this.initialized) {
+          if (
+            forceRestartlessInstall &&
+            !this.initialized &&
+            !Services.startup.attemptingQuit
+          ) {
             this.logger.debug("Forcing restartless install of train-hop");
             newInstall.continuePostponedInstall();
           } else {
             this.logger.debug("Not forcing restartless install");
             if (forceRestartlessInstall) {
               this.logger.debug(
-                "We must have initialized before the XPI finished downloading."
+                Services.startup.attemptingQuit
+                  ? "Application Shutdown already initiated"
+                  : "We must have initialized before the XPI finished downloading."
               );
             }
             deferred.resolve();
Assignee: nobody → lgreco
Flags: needinfo?(lgreco)

I'm removing the assignee implicitly set by bugzilla when I have attached the xpcshell test to demonstrate the role that appShutdownConfirmed blocker seems to have in triggering a shutdown hang, but as mentioned in comment 5 that patch is not meant to be landed (the test resorts to call Services.startup.quit to recreate the scenario).

Let's determine first if we feel that the rationale sounds reasonable and if the tweak described at the end of comment 5 feels like worth pursuing.

Assignee: lgreco → nobody
Flags: needinfo?(mconley)

I've been thinking about this some more today and another middle ground approach may be to:

  • to not use an AsyncShutdown blocker anymore on the AboutNewTabResourceMapping side (as mentioned in comment 4), but to also add logic to bail out instead of calling newInstall.continuePostponedInstall by checking explicitly if Services.startup.attemptingQuit is true in the onInstallPostponed (similar to the diff at the end of comment 5)

  • and to leave to the AsyncShutdown blockers on the XPIProvider side the responsability to deal with the XPIProvider's operations that may still be in progress while we are about to shutdown.

Looks like we're still seeing this spike every time a new trainhop addon ships. Anything we can do to get it moving forward again?

Looking again...

Hey rpl, I think your middle ground in comment 7 sounds very reasonable to me. Do you have time to review a patch if I take a crack at it?

Flags: needinfo?(mconley) → needinfo?(lgreco)

(In reply to Mike Conley (:mconley) (:⚙️) from comment #10)

Hey rpl, I think your middle ground in comment 7 sounds very reasonable to me. Do you have time to review a patch if I take a crack at it?

Hey Mike, sorry for not getting back to you sooner. Yes I'll be more than happy to give a review pass of the patch applying those changes, feel free to add me as the reviewer on the patch once you are putting it up on phabricator.

Flags: needinfo?(lgreco)
Duplicate of this bug: 2034710

According to crash ping data, this is currently the #2 highest main process crasher in release (and it could potentially be #1, since the #1 crasher is a mistaken signature that hides more AsyncShutdownTimeout signatures). This should be a high priority to fix, as it is linked with elevated crash rates on Linux and Windows over the past few months.

scheduleUpdateTrainhopAddonState registered an AsyncShutdown.appShutdownConfirmed
blocker that awaited _updateAddonStateDeferredTask.finalize(). That tied application
shutdown to the completion of a train-hop XPI download/install, producing the
AsyncShutdownTimeout | quit-application | newtabTrainhopAddon scheduleUpdateTrainhopAddonState shutting down top crash.

Bug 1991490 relied on DownloadAddonInstall's quit-application-granted observer to
cancel an in-flight download, but that notification is one-shot and is fired before
AppShutdownConfirmed. If the deferred task is anywhere in its await chain
(NimbusFeatures.ready(), AddonManager.getAddonByID, getAllInstalls,
getInstallForURL, ...) when it fires, the install started afterwards registers its
observer too late, is never cancelled, and the blocker hangs until the AsyncShutdown
timeout kills the process. There is also no shutdown handling at all during the
post-download staging window (onStopRequest removes both observers before staging).

Rather than papering over that race, take the middle-ground approach agreed in comment 7:

  • Drop the AsyncShutdown blocker entirely. Interrupting the update is safe: an already
    staged install is applied on the next startup, and everything else is recomputed from
    the Nimbus enrollments next session. Finalizing XPIProvider operations that are still
    in progress is left to the XPIProvider's own AsyncShutdown blockers.
  • Add an _isAppShuttingDown() helper based on nsIAppStartup.attemptingQuit (the
    earliest signal, set before quit-application-granted is notified) plus the existing
    isInOrBeyondShutdownPhase(APPSHUTDOWNCONFIRMED) check, for shutdowns that don't go
    through nsIAppStartup.quit.
  • Use it to bail out of the deferred task, to avoid starting a download that could never
    be cancelled, and to avoid calling continuePostponedInstall() on the FirstStartup
    restartless path once shutdown has begun.

Adds test_nimbus_newtabTrainhopAddon_shutdown.js, which reproduces the hang: with a
stalled _installTrainhopAddon, triggering the appShutdownConfirmed barrier used to
block until the harness force-killed the process; it now returns immediately. It also
covers not starting a download and not forcing a restartless install during shutdown.

test_nimbus_newtabTrainhopAddon_onBrowserReady.js finalizes the deferred task directly
now that no blocker does it.

Assignee: nobody → mconley
Status: NEW → ASSIGNED
Attachment #9629504 - Attachment description: Bug 2016440 - Don't block application shutdown on the newtab train-hop update task. r=rpl → Bug 2016440 - Don't block application shutdown on the newtab train-hop update task. r=rpl!

Is it possible that this same bug is causing the AsyncShutdownTimeout | profile-before-change | AddonManager: shutting down. crash signature?

Pushed by mconley@mozilla.com: https://github.com/mozilla-firefox/firefox/commit/f7b38cf3ac03 https://hg.mozilla.org/integration/autoland/rev/b68e34112684 Don't block application shutdown on the newtab train-hop update task. r=rpl,thecount,fchasen
Status: ASSIGNED → RESOLVED
Closed: 1 month ago
Resolution: --- → FIXED
Target Milestone: --- → 157 Branch

The patch landed in nightly and beta is affected.
:mconley, is this bug important enough to require an uplift?

For more information, please visit BugBot documentation.

Flags: needinfo?(mconley)

scheduleUpdateTrainhopAddonState registered an AsyncShutdown.appShutdownConfirmed
blocker that awaited _updateAddonStateDeferredTask.finalize(). That tied application
shutdown to the completion of a train-hop XPI download/install, producing the
AsyncShutdownTimeout | quit-application | newtabTrainhopAddon scheduleUpdateTrainhopAddonState shutting down top crash.

To fix this, we now:

  • Drop the AsyncShutdown blocker entirely. Interrupting the update is safe: an already
    staged install is applied on the next startup, and everything else is recomputed from
    the Nimbus enrollments next session. Finalizing XPIProvider operations that are still
    in progress is left to the XPIProvider's own AsyncShutdown blockers.
  • Add an _isAppShuttingDown() helper based on nsIAppStartup.attemptingQuit (the
    earliest signal, set before quit-application-granted is notified) plus the existing
    isInOrBeyondShutdownPhase(APPSHUTDOWNCONFIRMED) check, for shutdowns that don't go
    through nsIAppStartup.quit.
  • Use it to bail out of the deferred task, to avoid starting a download that could never
    be cancelled, and to avoid calling continuePostponedInstall() on the FirstStartup
    restartless path once shutdown has begun.

Original Revision: https://phabricator.services.mozilla.com/D320515

Attachment #9635889 - Flags: approval-mozilla-beta?

firefox-beta Uplift Approval Request

  • User impact if declined/Reason for urgency: We believe this will address a top shutdown crash that occurs when download of a newtab trainhop XPI is only partially completed at shutdown.
  • Code covered by automated testing?: yes
  • Fix verified in Nightly?: no
  • Needs manual QE testing?: no
  • Steps to reproduce for manual QE testing:
  • Risk associated with taking this patch: low
  • Explanation of risk level: This removes an AsyncShutdown blocker within the mechanism that downloads and installs the newtab trainhop XPI. The goal is to get this uplifted to Beta and do a trainhop to that channel in order to ensure that the deployment mechanism still works and that the crashes have gone.
  • String changes made/needed?: None.
  • Is Android affected?: no
Attachment #9635889 - Flags: approval-mozilla-beta? → approval-mozilla-beta+
Flags: needinfo?(mconley)
QA Whiteboard: [qa-triage-done-c157/b156]
Duplicate of this bug: 2070489
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: