1322931 - Firefox won't update as limited user even with maintenance service

Status: RESOLVED INVALID

(Toolkit :: Application Update, defect)

Description

[Dominic]

The Mozilla Maintenance Service is there to apply updates when limited user accounts want to update the product and the user itself doesn't has the permission for that. Whenever I hit the update button in the about view of the browser, Firefox itself closes and after that, opens up immediately with the window from the updater, that says, that the update failed.

The reason is every time the same: Patch apply failed.
I tried to reinstall Firefox and even the Maintenance Service itself. The service seems, that it won't start.

Reproducible: Always

Comment 1

[Molly Howell (she/her) (mostly inactive)]

It is possible for the maintenance service to be disabled, even when it's correctly installed. Check in Options in the Advanced page under the Update tab and make sure that "Use a background service to install updates" is checked.

If that's already checked, then we'll need to get more detailed logs from the update client. Follow the instructions at [https://support.mozilla.org/en-US/kb/about-config-editor-firefox] to open the configuration editor, search for the preference called app.update.log and toggle it to true. Then, open the Browser Console either by selecting it from the Developer menu (wrench icon) or pressing Ctrl+Shift+J. Then open the About window. You should see some lines that start with "AUS:SVC" appear in the browser console; copy those lines and paste them in here. That should tell us more about what's going on with the maintenance service.

Comment 2

[Dominic]

When I hit the about Button, there is a message, that it downloads the update..


This is my console Log (I sourrounded the console with hash keys '#' for better readability)

#########################################################################################################################################
AUS:SVC Checker: checkForUpdates, force: true
AUS:SVC Checker:getUpdateURL - update URL: https://aus5.mozilla.org/update/6/Firefox/53.0a1/20161211030209/WINNT_x86_64-msvc-x64/en-US/nightly/Windows_NT%2010.0.0.0%20(x64)(noBug1296630v1)/SSE3/default/default/update.xml?force=1
AUS:SVC Checker:checkForUpdates - sending request to: https://aus5.mozilla.org/update/6/Firefox/53.0a1/20161211030209/WINNT_x86_64-msvc-x64/en-US/nightly/Windows_NT%2010.0.0.0%20(x64)(noBug1296630v1)/SSE3/default/default/update.xml?force=1
AUS:SVC Checker:onLoad - request completed downloading document
AUS:SVC Checker:getUpdateURL - update URL: https://aus5.mozilla.org/update/6/Firefox/53.0a1/20161211030209/WINNT_x86_64-msvc-x64/en-US/nightly/Windows_NT%2010.0.0.0%20(x64)(noBug1296630v1)/SSE3/default/default/update.xml?force=1
AUS:SVC Checker:onLoad - number of updates available: 1
AUS:SVC isServiceInstalled = true
AUS:SVC getCanApplyUpdates - bypass the write checks because we'll use the service
AUS:SVC getCanApplyUpdates - able to apply updates
AUS:SVC Creating Downloader
AUS:SVC UpdateService:_downloadUpdate
AUS:SVC readStringFromFile - file doesn't exist: C:\Users\User\AppData\Local\Mozilla\updates\A3710B8EBB50CD3\updates\0\update.status
AUS:SVC readStatusFile - status: null, path: C:\Users\User\AppData\Local\Mozilla\updates\A3710B8EBB50CD3\updates\0\update.status
AUS:SVC Downloader:downloadUpdate - url: https://mozilla-nightly-updates.s3.amazonaws.com/mozilla-central/20161212030206/Firefox-mozilla-central-53.0a1-win64-en-US-20161211030209-20161212030206.partial.mar?versionId=vV_iof8JYGyRCUTSqabLmFz.vic7tSy0, path: C:\Users\User\AppData\Local\Mozilla\updates\A3710B8EBB50CD3\updates\0\update.mar, interval: 0
AUS:SVC Downloader:onStartRequest - original URI spec: https://mozilla-nightly-updates.s3.amazonaws.com/mozilla-central/20161212030206/Firefox-mozilla-central-53.0a1-win64-en-US-20161211030209-20161212030206.partial.mar?versionId=vV_iof8JYGyRCUTSqabLmFz.vic7tSy0, final URI spec: https://mozilla-nightly-updates.s3.amazonaws.com/mozilla-central/20161212030206/Firefox-mozilla-central-53.0a1-win64-en-US-20161211030209-20161212030206.partial.mar?versionId=vV_iof8JYGyRCUTSqabLmFz.vic7tSy0
AUS:SVC Downloader:onProgress - progress: 1310720/7246256
AUS:SVC Downloader:onProgress - progress: 7246256/7246256
AUS:SVC Downloader:onStopRequest - original URI spec: https://mozilla-nightly-updates.s3.amazonaws.com/mozilla-central/20161212030206/Firefox-mozilla-central-53.0a1-win64-en-US-20161211030209-20161212030206.partial.mar?versionId=vV_iof8JYGyRCUTSqabLmFz.vic7tSy0, final URI spec: https://mozilla-nightly-updates.s3.amazonaws.com/mozilla-central/20161212030206/Firefox-mozilla-central-53.0a1-win64-en-US-20161211030209-20161212030206.partial.mar?versionId=vV_iof8JYGyRCUTSqabLmFz.vic7tSy0, status: 0
AUS:SVC Downloader:onStopRequest - status: 0, current fail: 0, max fail: 10, retryTimeout: 2000
AUS:SVC Downloader:_verifyDownload called
AUS:SVC Downloader:_verifyDownload downloaded size == expected size.
AUS:SVC isServiceInstalled = true
AUS:SVC Downloader:onStopRequest - setting state to: pending-service
AUS:SVC isServiceInstalled = true
AUS:SVC getCanStageUpdates - able to stage updates using the service
AUS:SVC isServiceInstalled = true
AUS:SVC getCanStageUpdates - able to stage updates using the service
AUS:SVC Downloader:onStopRequest - attempting to stage update: Nightly 53.0a1
#########################################################################################################################################

Now, the spinner from the appying update message stucks about 10 Minutes. I closed the window, because it seems to stuck.
After reopening the browser about window, there is a restart button. When I click it, the browser restarts.
After the new start, I opened the console again and there was this written:

#########################################################################################################################################
Unrecognized chrome manifest modifier 'locale/ar/'.  chrome.manifest:5
Unrecognized chrome manifest modifier 'locale/ca/'.  chrome.manifest:7
Unrecognized chrome manifest modifier 'locale/de/'.  chrome.manifest:9
Unrecognized chrome manifest modifier 'locale/el/'.  chrome.manifest:11
Unrecognized chrome manifest modifier 'locale/es-es/'.  chrome.manifest:15
Unrecognized chrome manifest modifier 'locale/fi/'.  chrome.manifest:19
Unrecognized chrome manifest modifier 'locale/fr/'.  chrome.manifest:21
Unrecognized chrome manifest modifier 'locale/id/'.  chrome.manifest:23
Unrecognized chrome manifest modifier 'locale/it/'.  chrome.manifest:25
Unrecognized chrome manifest modifier 'locale/ja/'.  chrome.manifest:27
Unrecognized chrome manifest modifier 'locale/pl/'.  chrome.manifest:31
Unrecognized chrome manifest modifier 'locale/pt-br/'.  chrome.manifest:33
Unrecognized chrome manifest modifier 'locale/tr/'.  chrome.manifest:37
Unrecognized chrome manifest modifier 'locale/zh-tw/'.  chrome.manifest:41
Warning: ‘nsIOService::NewChannel()’ deprecated, please use ‘nsIOService::NewChannel2()’  bootstrap.js:45:16
expression closures are deprecated  bootstrap.js:27:18
UTM:SVC TimerManager:registerTimer - id: xpi-signature-verification
AUS:SVC Creating UpdateService
AUS:SVC readStatusFile - status: pending-service, path: C:\Users\User\AppData\Local\Mozilla\updates\A3710B8EBB50CD3\updates\0\update.status
UTM:SVC TimerManager:registerTimer - id: browser-cleanup-thumbnails
1481574114449	addons.webextension.rested@restedclient	WARN	Loading extension 'rested@restedclient': Reading manifest: Error processing contributors: An unexpected property was found in the WebExtension manifest.
1481574114450	addons.webextension.rested@restedclient	WARN	Loading extension 'rested@restedclient': Reading manifest: Error processing license: An unexpected property was found in the WebExtension manifest.
1481574114471	addons.webextension.rested@restedclient	WARN	Please specify whether you want browser_style or not in your browser_action options.
Synchronous XMLHttpRequest on the main thread is deprecated because of its detrimental effects to the end user’s experience. For more help http://xhr.spec.whatwg.org/  import.js:223:4
AUS:SVC gCanCheckForUpdates - able to check for updates
AUS:SVC isServiceInstalled = true
AUS:SVC getCanApplyUpdates - bypass the write checks because we'll use the service
AUS:SVC getCanApplyUpdates - able to apply updates
AUS:SVC readStatusFile - status: pending-service, path: C:\Users\User\AppData\Local\Mozilla\updates\A3710B8EBB50CD3\updates\0\update.status
AUS:SVC handleFallbackToCompleteUpdate - install of partial patch failed, downloading complete patch
AUS:SVC Creating Downloader
AUS:SVC UpdateService:_downloadUpdate
AUS:SVC readStringFromFile - file doesn't exist: C:\Users\User\AppData\Local\Mozilla\updates\A3710B8EBB50CD3\updates\0\update.status
AUS:SVC readStatusFile - status: null, path: C:\Users\User\AppData\Local\Mozilla\updates\A3710B8EBB50CD3\updates\0\update.status
AUS:SVC Downloader:_selectPatch - found existing patch with state: null
AUS:SVC Downloader:downloadUpdate - url: https://mozilla-nightly-updates.s3.amazonaws.com/mozilla-central/20161212030206/Firefox-mozilla-central-53.0a1-win64-en-US.complete.mar?versionId=6IL1kK7F7W7vJvEKBZ_FQ15l8Vh53bF_, path: C:\Users\User\AppData\Local\Mozilla\updates\A3710B8EBB50CD3\updates\0\update.mar, interval: 0
NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsISerializationHelper.deserializeObject]  Utils.jsm:94
AUS:UI gUpdates:onLoad - setting current page to startpage errorpatching
AUS:SVC Downloader:onStartRequest - original URI spec: https://mozilla-nightly-updates.s3.amazonaws.com/mozilla-central/20161212030206/Firefox-mozilla-central-53.0a1-win64-en-US.complete.mar?versionId=6IL1kK7F7W7vJvEKBZ_FQ15l8Vh53bF_, final URI spec: https://mozilla-nightly-updates.s3.amazonaws.com/mozilla-central/20161212030206/Firefox-mozilla-central-53.0a1-win64-en-US.complete.mar?versionId=6IL1kK7F7W7vJvEKBZ_FQ15l8Vh53bF_
AUS:SVC Downloader:onProgress - progress: 16980/52999282
Use of nsIFile in content process is deprecated.  loader.js:244:15
AUS:SVC Downloader:onProgress - progress: 191060/52999282
AUS:SVC Downloader:onProgress - progress: 608852/52999282
AUS:SVC Downloader:onProgress - progress: 1879636/52999282
AUS:SVC Downloader:onProgress - progress: 4682324/52999282
AUS:SVC Downloader:onProgress - progress: 9397796/52999282
AUS:SVC Downloader:onProgress - progress: 16131356/52999282
AUS:SVC Downloader:onProgress - progress: 21456420/52999282
AUS:SVC Downloader:onProgress - progress: 25994668/52999282
AUS:SVC Downloader:onProgress - progress: 28583388/52999282
AUS:SVC Downloader:onProgress - progress: 32843132/52999282
AUS:SVC Downloader:onProgress - progress: 38807004/52999282
AUS:SVC Downloader:onProgress - progress: 44852724/52999282
AUS:SVC Downloader:onProgress - progress: 50783828/52999282
AUS:SVC Downloader:onProgress - progress: 52999282/52999282
AUS:SVC Downloader:onStopRequest - original URI spec: https://mozilla-nightly-updates.s3.amazonaws.com/mozilla-central/20161212030206/Firefox-mozilla-central-53.0a1-win64-en-US.complete.mar?versionId=6IL1kK7F7W7vJvEKBZ_FQ15l8Vh53bF_, final URI spec: https://mozilla-nightly-updates.s3.amazonaws.com/mozilla-central/20161212030206/Firefox-mozilla-central-53.0a1-win64-en-US.complete.mar?versionId=6IL1kK7F7W7vJvEKBZ_FQ15l8Vh53bF_, status: 0
AUS:SVC Downloader:onStopRequest - status: 0, current fail: 0, max fail: 10, retryTimeout: 2000
AUS:SVC Downloader:_verifyDownload called
AUS:SVC Downloader:_verifyDownload downloaded size == expected size.
AUS:SVC isServiceInstalled = true
AUS:SVC getCanStageUpdates - able to stage updates using the service
AUS:SVC Downloader:onStopRequest - setting state to: pending-service
AUS:SVC isServiceInstalled = true
AUS:SVC getCanStageUpdates - able to stage updates using the service
AUS:SVC Downloader:onStopRequest - attempting to stage update: Nightly 53.0a1
Key event not available on some keyboard layouts: key=“r” modifiers=“accel,alt” id=“toggleReaderMode”  browser.xul
Key event not available on some keyboard layouts: key=“i” modifiers=“accel,alt,shift” id=“key_browserToolbox”  browser.xul
#########################################################################################################################################

With the browser, there opens a window, saying, that the partial update failed. It tries to manage a complete update. I press okay.

#########################################################################################################################################
AUS:UI gFinishedPage:not elevationRequired
#########################################################################################################################################

Now, there appears a restart button instead of the okay button. I press it and the browser restarts.

#########################################################################################################################################
Unrecognized chrome manifest modifier 'locale/ar/'.  chrome.manifest:5
Unrecognized chrome manifest modifier 'locale/ca/'.  chrome.manifest:7
Unrecognized chrome manifest modifier 'locale/de/'.  chrome.manifest:9
Unrecognized chrome manifest modifier 'locale/el/'.  chrome.manifest:11
Unrecognized chrome manifest modifier 'locale/es-es/'.  chrome.manifest:15
Unrecognized chrome manifest modifier 'locale/fi/'.  chrome.manifest:19
Unrecognized chrome manifest modifier 'locale/fr/'.  chrome.manifest:21
Unrecognized chrome manifest modifier 'locale/id/'.  chrome.manifest:23
Unrecognized chrome manifest modifier 'locale/it/'.  chrome.manifest:25
Unrecognized chrome manifest modifier 'locale/ja/'.  chrome.manifest:27
Unrecognized chrome manifest modifier 'locale/pl/'.  chrome.manifest:31
Unrecognized chrome manifest modifier 'locale/pt-br/'.  chrome.manifest:33
Unrecognized chrome manifest modifier 'locale/tr/'.  chrome.manifest:37
Unrecognized chrome manifest modifier 'locale/zh-tw/'.  chrome.manifest:41
Warning: ‘nsIOService::NewChannel()’ deprecated, please use ‘nsIOService::NewChannel2()’  bootstrap.js:45:16
expression closures are deprecated  bootstrap.js:27:18
UTM:SVC TimerManager:registerTimer - id: xpi-signature-verification
AUS:SVC Creating UpdateService
AUS:SVC readStatusFile - status: pending-service, path: C:\Users\User\AppData\Local\Mozilla\updates\A3710B8EBB50CD3\updates\0\update.status
UTM:SVC TimerManager:registerTimer - id: browser-cleanup-thumbnails
1481574210235	addons.webextension.rested@restedclient	WARN	Loading extension 'rested@restedclient': Reading manifest: Error processing contributors: An unexpected property was found in the WebExtension manifest.
1481574210235	addons.webextension.rested@restedclient	WARN	Loading extension 'rested@restedclient': Reading manifest: Error processing license: An unexpected property was found in the WebExtension manifest.
1481574210257	addons.webextension.rested@restedclient	WARN	Please specify whether you want browser_style or not in your browser_action options.
Synchronous XMLHttpRequest on the main thread is deprecated because of its detrimental effects to the end user’s experience. For more help http://xhr.spec.whatwg.org/  import.js:223:4
AUS:SVC gCanCheckForUpdates - able to check for updates
AUS:SVC isServiceInstalled = true
AUS:SVC getCanApplyUpdates - bypass the write checks because we'll use the service
AUS:SVC getCanApplyUpdates - able to apply updates
AUS:SVC readStatusFile - status: pending-service, path: C:\Users\User\AppData\Local\Mozilla\updates\A3710B8EBB50CD3\updates\0\update.status
AUS:SVC handleFallbackToCompleteUpdate - install of complete or only one patch offered failed.
NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsISerializationHelper.deserializeObject]  Utils.jsm:94
AUS:UI gUpdates:onLoad - setting current page to startpage errors
AUS:UI gErrorsPage:onPageShow - update.statusText: The Update could not be installed (patch apply failed)
Use of nsIFile in content process is deprecated.  loader.js:244:15
Key event not available on some keyboard layouts: key=“r” modifiers=“accel,alt” id=“toggleReaderMode”  browser.xul
Key event not available on some keyboard layouts: key=“i” modifiers=“accel,alt,shift” id=“key_browserToolbox”  browser.xul
#########################################################################################################################################

There is again this window telling me, that update failed completetly. So, I press okay and the window closes.
Now, there happened no update or anything else. I am stuck in this update circle.

If I go to the about tab again, the routine reruns again... Stuck at the spinner ... and so on ..

Comment 3

[Molly Howell (she/her) (mostly inactive)]

Okay, thanks for posting those. I was hoping there would be some obvious reason logged for why the service wasn't used, but it looks like the browser tried to start the service, but then it never really started or just never actually did anything. Which means I have to ask you for more log files. There are two sets, one for the maintenance service and one for the rest of the update procedure.
The maintenance service log files are kept under its installation directory, in "C:\Program Files (x86)\Mozilla Maintenance Service\logs". If there is a file in there with a modified time set to when you last attempted an update, then please attach that file to this bug. If not, then that fact itself would be interesting.
To get to the updater logs, please go to "C:\Users\User\AppData\Local\Mozilla\updates\A3710B8EBB50CD3\updates" and attach any of the following files that exist in that directory (don't worry if one or two aren't there):
* last-update.log
* backup-update.log
* 0\update.log

Thanks again.

Comment 4

[Dominic]

You are right! I'm missing the 0\update.log file. 

Anyway here are the files, I have: 
"C:\Users\User\AppData\Local\Mozilla\updates\A3710B8EBB50CD3\updates":
* last-update.log
* backup-update.log

"C:\Program Files (x86)\Mozilla Maintenance Service\logs":
* maintenanceservice.log

I've attached the Files to the bug itself. But it looks like the browser tried to do an update today, because these Files have been updated today. I don't have the Files from yesterday.

The Maintenance Service update logs have been edited at 2016-12-11 so, there was no update log file for the 12/12/16. I've attached it anyway.

In the last-update.log, the browser logged, that the patch succeed, but at the about window, there is still the restart button.

Comment 5

[Dominic]

Attachment: The file from the Backup before the update "backup-update.log"

Comment 6

[Dominic]

Attachment: The update file itself "last-update.log"

Comment 7

[Dominic]

Attachment: The log from the Maintenance Service, created at 2016-12-11 "maintenanceservice.log"

Comment 8

[Dominic]

(In reply to Dominic from comment #5)
> Created attachment 8818282 [details]
> The file from the Backup before the update "backup-update.log"

Is it possible, that the browser hasn't enough permission to write to the C:\ drive for patching and creating backups?

Comment 9

[Molly Howell (she/her) (mostly inactive)]

Hmm. Okay, not too much of that made any sense. First, those updater logs look like a successful update happened. Did you actually end up with today's nightly (the about box should show the date next to the build number)? Second, I have no idea what to make of that maintenance service log. That error should not be possible unless the browser did something it cannot normally do.

All I have left to ask you to try at this point is updating from safe mode [https://support.mozilla.org/en-US/kb/troubleshoot-firefox-issues-using-safe-mode]. If that doesn't work, I'm out of ideas beyond reinstalling the browser.

Comment 10

[Dominic]

I tried that method you suggested. Something similar to the bug report happens: The browser downloads the update and gives me a button to restart. When I've restarted, the browser gives me the error, that the patch apply failed.
I've also noticed, that the Maintenance Service created an install log at 2016-12-11, even when I haven't updated or installed the service at my intention. Is that normal behavior?
For this, I tried your Idea to update in safe mode. So, there is no progress :(

However I noticed, that the browser itself creates a crash report every time. Here is a link for one of those: https://crash-stats.mozilla.com/report/index/3d46b0f1-5e38-42f5-b2c3-689032161215

Do you know, what the command line arguments for the updater service are, so that I can try to update using the updater service. If that works I know at least, that it is the browser itself and not the service. Then I can try to do some more digging.

The idea of reinstalling was also mine a few weeks ago. That is the reason, I've created a bug report. The re-installation of the browser hasn't fixed anything. :(

I have also the question, if it is possible to do an early log of the browsers activity (e.g. through command line) to get a more detailed look into this whole thing. maybe then I can find something.

Comment 11

[Wayne Mery (:wsmwk)]

Dominic
Does this still reproduce for you using a current version?

Comment 12

[Dominic]

Oh, I'm sorry. The Bug has been solved a year ago and I thought i changed the issue to fixed.
I reinstalled Windows and Firefox and now, it seems to work flawlessly.
Please excuse the inconvenience!