760027 - Software update failed with "The update could not be installed. Please make sure there are no other copies of Firefox running on your computer..."

Status: RESOLVED FIXED

(Toolkit :: Application Update, defect)

Description

[Jared Wein [:jaws] (please needinfo? me)]

"The update could not be installed. Please make sure there are no other copies of Firefox running on your computer, and then restart Firefox to try again."

This has happened to me twice since bug 307181 landed. I get this when going to the About dialog and clicking on the "Restart to update" button.

This only appears to happen after a long browsing session, where Firefox is slow to shut down.

I'll see if I can find the relevant logs to attach here.

Comment 1

[Jared Wein [:jaws] (please needinfo? me)]

Attachment: maintenanceservice.log

Date modified: 5/31/2012 2:47am

Comment 2

[Jared Wein [:jaws] (please needinfo? me)]

Attachment: maintenanceservice-1.log

Date modified: 5/31/2012 2:47am

Comment 3

[Jared Wein [:jaws] (please needinfo? me)]

Attachment: maintenanceservice-2.log

Date modified: 5/31/2012 2:40am

There are 7 more logs but the rest of them have date-modifieds of 5/30 and earlier. I can attach those too if they will help in diagnosing this.

Comment 4

[Brian R. Bondy [:bbondy]]

Thanks Jared, Ehsan it sounds like in  maintenanceservice-2.log  maybe the replace stage of the background updates is not waiting for firefox.exe to be shut down.

Comment 5

[Brian R. Bondy [:bbondy]]

Maybe adding a sleep at shutdown after the command is executed but before firefox.exe exits would help reproduce the problem consistently.

Comment 6

[Brian R. Bondy [:bbondy]]

actually from that log, I think that's a log from the apply stage, so I don't know what the problem is there.

Comment 7

[(no longer active)]

No, the log #2 is from the replace stage given the command line, and the fact that the updater is copied to the temp directory...

Something else which is puzzling is the other two logs.  Is there a case where this should happen with the service?

Comment 8

[(no longer active)]

Jared, can you please zip up your C:\Users\username\AppData\Local\Mozilla\Firefox directory and attach it here?

Also, once you've done that, can you see if you can reproduce this by downloading an older nightly and trying to update again?

Comment 9

[Brian R. Bondy [:bbondy]]

I suspect the other 2 logs are a different bug where not all args are passed in, probably somewhere after error code 7 happens.

Comment 10

[(no longer active)]

(In reply to Brian R. Bondy [:bbondy] from comment #9)
> I suspect the other 2 logs are a different bug where not all args are passed
> in, probably somewhere after error code 7 happens.

Hmm, that should not be happening at all...  That could be from the staging pass for example.  Let me read the code a bit...  Jared, if you can reproduce this in the future, could you see if you have this directory: C:\Program Files (x86)\Nightly\updated, and if you do, could you list its contents please?

Comment 11

[Brian R. Bondy [:bbondy]]

It'll only happen when you have 2 or less command line args sent to the service. Windows includes 2 on its own so that means there are 0 args sent to the service. 

You can get this exact error if you manually try to start Mozilla Maintenance Service from Administrative tools -> Services.  Maybe that's what Jared did for those 2 error logs?

Comment 12

[B.J. Herbison]

I've been receiving the message "The update could not be installed...." for the past week on Windows XP. I've only been able to update by new images from http://nightly.mozilla.org/ .

Would information would be useful to debug this issue? I can't find any  maintenanceservice.log file on my system using Windows file search.

Comment 13

[Brian R. Bondy [:bbondy]]

There's definitely something new going on here, but we've always gotten some error code 7's by the way.  This will also happen when people have 2 profiles running and try to do an update. 

Telemetry data before bgupdates landed:
error code 7: 1.8%

Telemetry data after bgupdates landed:
error code 7: 4.11%

Comment 14

[CruNcher]

Disabled unneeded token privilege: SeAssignPrimaryTokenPrivilege.
Disabled unneeded token privilege: SeAuditPrivilege.
Disabled unneeded token privilege: SeBackupPrivilege.
Disabled unneeded token privilege: SeCreateGlobalPrivilege.
Disabled unneeded token privilege: SeCreatePagefilePrivilege.
Disabled unneeded token privilege: SeCreatePermanentPrivilege.
Disabled unneeded token privilege: SeCreateSymbolicLinkPrivilege.
Could not disable token privilege value: SeCreateTokenPrivilege. (1300)
Disabled unneeded token privilege: SeDebugPrivilege.
Could not disable token privilege value: SeEnableDelegationPrivilege. (1300)
Disabled unneeded token privilege: SeImpersonatePrivilege.
Disabled unneeded token privilege: SeIncreaseBasePriorityPrivilege.
Disabled unneeded token privilege: SeIncreaseQuotaPrivilege.
Disabled unneeded token privilege: SeIncreaseWorkingSetPrivilege.
Disabled unneeded token privilege: SeLoadDriverPrivilege.
Disabled unneeded token privilege: SeLockMemoryPrivilege.
Could not disable token privilege value: SeMachineAccountPrivilege. (1300)
Disabled unneeded token privilege: SeManageVolumePrivilege.
Disabled unneeded token privilege: SeProfileSingleProcessPrivilege.
Could not disable token privilege value: SeRelabelPrivilege. (1300)
Could not disable token privilege value: SeRemoteShutdownPrivilege. (1300)
Disabled unneeded token privilege: SeRestorePrivilege.
Disabled unneeded token privilege: SeSecurityPrivilege.
Disabled unneeded token privilege: SeShutdownPrivilege.
Could not disable token privilege value: SeSyncAgentPrivilege. (1300)
Disabled unneeded token privilege: SeSystemEnvironmentPrivilege.
Disabled unneeded token privilege: SeSystemProfilePrivilege.
Disabled unneeded token privilege: SeSystemtimePrivilege.
Disabled unneeded token privilege: SeTakeOwnershipPrivilege.
Disabled unneeded token privilege: SeTcbPrivilege.
Disabled unneeded token privilege: SeTimeZonePrivilege.
Could not disable token privilege value: SeTrustedCredManAccessPrivilege. (1300)
Disabled unneeded token privilege: SeUndockPrivilege.
Could not disable token privilege value: SeUnsolicitedInputPrivilege. (1313)
Executing service command clear-prefetch, ID: ea51fc5e-1102-490b-8e1c-4e3574ead130
Service command not recognized: clear-prefetch.
service command MozillaMaintenance complete with result: Failure.


This is the issue i have trying to update from the 28th may build :(

Comment 15

[Brian R. Bondy [:bbondy]]

CruNcher:
You would need to attach a zip of all logs, those logs can be safely ignored. 
Anything with "Service command not recognized: clear-prefetch." is just using an old service but having the prefetch task and is known to be ok and safe.

Comment 16

[CruNcher]

 i think i might have found whats going on a 3rd party didn't closed a handle when executing firefox.exe but this never caused problems with the old update system now it seems much more picky ill try to find all handles and see if that fixes this though i must say the old update system was much more robust :(

Comment 17

[(no longer active)]

(In reply to CruNcher from comment #16)
>  i think i might have found whats going on a 3rd party didn't closed a
> handle when executing firefox.exe but this never caused problems with the
> old update system now it seems much more picky ill try to find all handles
> and see if that fixes this though i must say the old update system was much
> more robust :(

Which third party application are you using?

Comment 18

[CruNcher]

I was reporting a bug for another Software Nexus Mod Manager http://skyrim.nexusmods.com/content/modmanager/ and i did this by using the in Application Help Menu which links to their Bug forum and Firefox was executed from there, now i closed the Application the handle to the firefox folder was freed and the update of Firefox worked and i have to write another bug report ;)
Thx Brian, though such things wouldn't have happened with the old update so as i said everyone has now to be triple more careful :)

Comment 19

[Brian R. Bondy [:bbondy]]

I talked to Jared on IRC...

The first logs were confirmed to be from restarting the service manually. So those can be safely ignored.

Jared also mentioned that he doesn't think he had a folder open nor third party softwrae that would have caused error code 7.

I still think this may be a duplicate of Bug 757907 though and adding better handling there may fix this.

Comment 20

[CruNcher]

Btw i wasn't really aware anymore that i started Firefox this way as i was using it afterwards heavily. I guess many more applications will just leave the handle open @ their entire runtime until closed and as long this is the case Firefox can't be anymore updated currently :(
I guess your telemetry data might be skyrocketing soon ;)

Comment 21

[(no longer active)]

(In reply to CruNcher from comment #18)
> I was reporting a bug for another Software Nexus Mod Manager
> http://skyrim.nexusmods.com/content/modmanager/ and i did this by using the
> in Application Help Menu which links to their Bug forum and Firefox was
> executed from there, now i closed the Application the handle to the firefox
> folder was freed and the update of Firefox worked and i have to write
> another bug report ;)
> Thx Brian, though such things wouldn't have happened with the old update so
> as i said everyone has now to be triple more careful :)

This should be improved with bug 757965.

Comment 22

[Jared Wein [:jaws] (please needinfo? me)]

Brian, the steps that you describe in bug 757907 describe exactly what was happening for me (with the exception of the cmd prompt open to the Nightly directory).

Comment 23

[Brian R. Bondy [:bbondy]]

Jared could you attach these files:
C:\Users\<username>\AppData\Local\Mozilla\Firefox\Nightly\updates
last-update.log
backup-update.log

Thanks!

Comment 24

[Jared Wein [:jaws] (please needinfo? me)]

I checked in my Nightly\updates folder and the two log files there both showed no mention of errors (they had been overwritten with newer logs). If I run in to the issue again I'll attach those logs here.

Comment 25

[Jared Wein [:jaws] (please needinfo? me)]

I also tried installing the 5/28 Nightly and opening 50+ GMail tabs, then going to Help -> About and restarting to update. I can watch firefox.exe take a long time to close (in Task Manager) but it does close cleanly and restarts with the update without an issue.

Comment 26

[(no longer active)]

Attachment: Attempt to retry the replace operation if it fails for some reason on Windows

As discussed on irc.

Comment 27

[Brian R. Bondy [:bbondy]]

Comment on attachment 628861 [details] [diff] [review]
Attempt to retry the replace operation if it fails for some reason on Windows

Review of attachment 628861 [details] [diff] [review]:
-----------------------------------------------------------------

::: toolkit/mozapps/update/updater/updater.cpp
@@ +1821,5 @@
> +  // Therefore we wait a little bit here to see if the handle is released.
> +  // If it's not released, we just fail to perform the replace request.
> +  const int max_retries = 10;
> +  int retries = 0;
> +  while (rv && (retries++ < max_retries)) {

We should break out early when the error doesn't match the one we would expect when there is a handle open (I think 7).

@@ +1826,5 @@
> +    LOG(("PerformReplaceRequest: sourceDir rename attempt %d failed. " \
> +         "File: " LOG_S ". Last error: %d, err: %d\n", retries,
> +         sourceDir, GetLastError(), rv));
> +
> +    Sleep(100);

We shouldn't sleep if there are no errors

Comment 28

[(no longer active)]

(In reply to Brian R. Bondy [:bbondy] from comment #27)
> Comment on attachment 628861 [details] [diff] [review]
> Attempt to retry the replace operation if it fails for some reason on Windows
> 
> Review of attachment 628861 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: toolkit/mozapps/update/updater/updater.cpp
> @@ +1821,5 @@
> > +  // Therefore we wait a little bit here to see if the handle is released.
> > +  // If it's not released, we just fail to perform the replace request.
> > +  const int max_retries = 10;
> > +  int retries = 0;
> > +  while (rv && (retries++ < max_retries)) {
> 
> We should break out early when the error doesn't match the one we would
> expect when there is a handle open (I think 7).

Good point (it's EACCES, or 13).

> @@ +1826,5 @@
> > +    LOG(("PerformReplaceRequest: sourceDir rename attempt %d failed. " \
> > +         "File: " LOG_S ". Last error: %d, err: %d\n", retries,
> > +         sourceDir, GetLastError(), rv));
> > +
> > +    Sleep(100);
> 
> We shouldn't sleep if there are no errors

We don't.  The loop condition will prevent against that.

Comment 29

[(no longer active)]

Attachment: Address bbondy's comment

Comment 30

[Brian R. Bondy [:bbondy]]

Comment on attachment 629031 [details] [diff] [review]
Address bbondy's comment

Review of attachment 629031 [details] [diff] [review]:
-----------------------------------------------------------------

::: toolkit/mozapps/update/updater/updater.cpp
@@ +1821,5 @@
>    // Therefore we wait a little bit here to see if the handle is released.
>    // If it's not released, we just fail to perform the replace request.
>    const int max_retries = 10;
>    int retries = 0;
> +  while (rv == EACCES && (retries++ < max_retries)) {

NS_trename returns false and sets errno on an error, but rename_file in updater.cpp actually returns WRITE_ERROR which is error code 7, not 13.

Please fix and then carry forward the r+.

Comment 31

[(no longer active)]

(In reply to Brian R. Bondy [:bbondy] from comment #30)
> Comment on attachment 629031 [details] [diff] [review]
> Address bbondy's comment
> 
> Review of attachment 629031 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: toolkit/mozapps/update/updater/updater.cpp
> @@ +1821,5 @@
> >    // Therefore we wait a little bit here to see if the handle is released.
> >    // If it's not released, we just fail to perform the replace request.
> >    const int max_retries = 10;
> >    int retries = 0;
> > +  while (rv == EACCES && (retries++ < max_retries)) {
> 
> NS_trename returns false and sets errno on an error, but rename_file in
> updater.cpp actually returns WRITE_ERROR which is error code 7, not 13.
> 
> Please fix and then carry forward the r+.

Ah, you're right!

Comment 32

[(no longer active)]

Attachment: Address bbondy's comment

Comment 33

[Brian R. Bondy [:bbondy]]

Comment on attachment 629179 [details] [diff] [review]
Address bbondy's comment

Review of attachment 629179 [details] [diff] [review]:
-----------------------------------------------------------------

Looks good, thanks!

Comment 34

[(no longer active)]

Attachment: Patch for landing

Comment 35

[(no longer active)]

https://hg.mozilla.org/mozilla-central/rev/1a28fcd25143

Comment 36

[Paul [pwd]]

Can this be reopened? I'm got this around 10 times for yesterday's nightly build and am unable to update to today's nightly build.

Comment 37

[(no longer active)]

(In reply to Paul [sabret00the] from comment #36)
> Can this be reopened? I'm got this around 10 times for yesterday's nightly
> build and am unable to update to today's nightly build.

Bug 760577 is tracking a better fix for this problem.

Comment 38

[Paul [pwd]]

I'm seeing this again.