1774745 - restart to apply application update is slow, pause of several seconds

Status: RESOLVED INCOMPLETE

(Toolkit :: Application Update, defect)

Description

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

Since the last ~2 weeks, Nightly 103.0a1 updates on this Windows 8.1 machine have a pause of several seconds (~8s) when nothing seems to happen.

Steps to reproduce here:

1. Have a Firefox installation for which an update is available.
2. Check for the update from menu Help > About Firefox.
3. After the update has been downloaded, press the button to restart now.

Firefox closes and the task manager lists an updater.exe with a helper.exe as child process. Before, this would proceed fast by spawning new firefox.exe processes and completing the update but it remains in this state for several seconds (~8s) before this can be observed now.

Comment 1

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

The most likely cause is that Firefox isn't staging successfully, so it has to do the whole update while Firefox is starting. Can you collect an update service log so that I can see what is going on with staging? In order to get what I need, the log is actually going to have to capture downloading and preparing an update, so you should either do this when an update should be ready to download, or you should install an old version so that you know an update will be available.

1. Navigate to about:config.
2. Set app.update.log to true.
3. Open the Browser Console either with the hotkey Control+Shift+J (Command+Shift+J on macOS), or via Hamburger Menu->More Tools->Browser Console
4. In the Filter textbox at the top, enter AUS:SVC to filter out everything except the update messages.
5. Navigate to the "Update" section of about:preferences or the Help -> About Firefox dialog. The Update UI should automatically check for an update.
6. Once the update is ready to install, copy the messages out of the Browser Console and attach them to this bug.

If staging is failing, it may also be useful if you collect an updater log right after staging fails:

1. Navigate to about:support
2. Find the "Update Folder" entry and click "Open Folder".
3. Open the updates directory.
4. Inside, you should find last-update.log. Attach it to this bug. Also, just to be sure that the log will have what we want, could you check the file modification time on the log and make sure that it approximately matches the time you collected the update service log? If, for some reason, the log there is really out of date, it would be good to know that.

Comment 2

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

Attachment: update_staging.log

Comment 3

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

Attachment: last-update.log

Comment 4

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

I think you cut off the first log before staging was complete. But the other log that you sent me is from a replace request (installing an already staged update). So it looks like staging is happening successfully.

I do see from the log that it has to try a couple of times to move the installation directory out of the way. I think that this is because Firefox is taking a long time to exit. I'm a little confused by that because I'm pretty sure that running files can be moved on Windows. In fact, I'm pretty sure that the updater binary is also in that directory and gets moved during that same call. But the error given is error 32, ERROR_SHARING_VIOLATION. And the comment explaining that retry code spells out exactly that as being the reason we are retrying that move.

It still seems odd though. We do a maximum of 10 retries, sleeping 100ms between each. So it shouldn't really account for more than about a half second of wait time. But it is possible that we are sleeping longer, since sleep time isn't guaranteed to be accurate.

It would be helpful for figuring this out if update logs had timestamps. I've been meaning to look into adding those for a while. I filed Bug 1775522 to do that.

In the meantime, maybe you could just look in the task manager and check if the firefox.exe process is running for most of the update time? If it is, that would clear up what the problem is.

Comment 5

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

Thank you for investigating.

(In reply to Kirk Steuber (he/him) [:bytesized] from comment #4)

In the meantime, maybe you could just look in the task manager and check if the firefox.exe process is running for most of the update time? If it is, that would clear up what the problem is.

Not of this Firefox installation.

During some manual bisection of a different issue with an older firefox unpacked into a different directory, I also encountered that firefox.exe as idling on start. This points to a an issue outside the build, likely antivirus/security software. This bug could be closed until we get more reports from other people.