944774 - Holly is not applying nightly updates on windows

Status: RESOLVED FIXED

(Release Engineering :: General, defect)

Description

[Mike Conley (:mconley) (:⚙️)]

STR:

1. Download firefox-28.0a1.en-US.win32.zip from http://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/2013-11-27-04-02-05-holly/
2. Extract it
3. Start nightly Holly build
4. Help > About Holly, and Click "Check for Updates" button

ER:

Update should apply, and an offer to restart to update presented.

AR:

Update fails, and user is instructed to download the new nightly directly.


Here's the AUS log:  https://pastebin.mozilla.org/3690254
Here's the contents of my HKEY_LOCAL_MACHINE\SOFTWARE\Mozilla\MaintenanceService: https://pastebin.mozilla.org/3690288

Comment 1

[[e-mail] (:bhearsum)]

For posterity, the AUS log:
AUS:SVC Creating UpdateService
AUS:SVC Checker: checkForUpdates, force: true
AUS:SVC getLocale - getting locale from file: resource://gre/update.locale, locale: en-US
AUS:SVC Checker:getUpdateURL - update URL: https://aus4.mozilla.org/update/3/Firefox/28.0a1/20131128040202/WINNT_x86-msvc/en-US/nightly-holly/Windows_NT%206.1.1.0%20(x64)/default/default/update.xml?force=1
AUS:SVC gCanCheckForUpdates - able to check for updates
AUS:SVC Checker:checkForUpdates - sending request to: https://aus4.mozilla.org/update/3/Firefox/28.0a1/20131128040202/WINNT_x86-msvc/en-US/nightly-holly/Windows_NT%206.1.1.0%20(x64)/default/default/update.xml?force=1
GET https://aus4.mozilla.org/update/3/Firefox/28.0a1/20131128040202/WINNT_x86-msvc/en-US/nightly-holly/Windows_NT%206.1.1.0%20(x64)/default/default/update.xml [HTTP/1.1 200 OK 329ms]
POST http://ocsp.digicert.com/ [HTTP/1.1 200 OK 30ms]
POST http://ocsp.digicert.com/ [HTTP/1.1 200 OK 14ms]
AUS:SVC Checker:onLoad - request completed downloading document
AUS:SVC Checker:getUpdateURL - update URL: https://aus4.mozilla.org/update/3/Firefox/28.0a1/20131128040202/WINNT_x86-msvc/en-US/nightly-holly/Windows_NT%206.1.1.0%20(x64)/default/default/update.xml?force=1
AUS:SVC Checker:onLoad - number of updates available: 1
AUS:SVC isServiceInstalled = true
AUS:SVC gCanApplyUpdates - bypass the write checks because we'll use the service
AUS:SVC gCanApplyUpdates - able to apply updates
AUS:SVC Creating Downloader
AUS:SVC UpdateService:_downloadUpdate
AUS:SVC readStringFromFile - file doesn't exist: C:\Users\mconley\AppData\Local\Mozilla\Firefox\firefox\updates\0\update.status
AUS:SVC readStatusFile - status: null, path: C:\Users\mconley\AppData\Local\Mozilla\Firefox\firefox\updates\0\update.status
AUS:SVC Downloader:downloadUpdate - downloading from http://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/2013/11/2013-11-29-04-02-02-holly/firefox-28.0a1.en-US.win32.partial.20131128040202-20131129040202.mar to C:\Users\mconley\AppData\Local\Mozilla\Firefox\firefox\updates\0\update.mar
AUS:SVC Downloader:onStartRequest - original URI spec: http://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/2013/11/2013-11-29-04-02-02-holly/firefox-28.0a1.en-US.win32.partial.20131128040202-20131129040202.mar, final URI spec: http://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/2013/11/2013-11-29-04-02-02-holly/firefox-28.0a1.en-US.win32.partial.20131128040202-20131129040202.mar
AUS:SVC Downloader:onProgress - progress: 786432/4647516
AUS:SVC Downloader:onProgress - progress: 4647516/4647516
AUS:SVC Downloader:onStopRequest - original URI spec: http://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/2013/11/2013-11-29-04-02-02-holly/firefox-28.0a1.en-US.win32.partial.20131128040202-20131129040202.mar, final URI spec: http://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/2013/11/2013-11-29-04-02-02-holly/firefox-28.0a1.en-US.win32.partial.20131128040202-20131129040202.mar, 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 Downloader:_verifyDownload hashes match.
AUS:SVC Downloader:onStopRequest - setting state to: pending-service
AUS:SVC getCanStageUpdates - able to stage updates because we'll use the service
AUS:SVC Downloader:onStopRequest - attempting to stage update: Holly 28.0a1
AUS:SVC readStatusFile - status: failed: 19, path: C:\Users\mconley\AppData\Local\Mozilla\Firefox\firefox\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\mconley\AppData\Local\Mozilla\Firefox\firefox\updates\0\update.status
AUS:SVC readStatusFile - status: null, path: C:\Users\mconley\AppData\Local\Mozilla\Firefox\firefox\updates\0\update.status
AUS:SVC Downloader:_selectPatch - found existing patch with state: null
AUS:SVC Downloader:downloadUpdate - downloading from http://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/2013/11/2013-11-29-04-02-02-holly/firefox-28.0a1.en-US.win32.complete.mar to C:\Users\mconley\AppData\Local\Mozilla\Firefox\firefox\updates\0\update.mar
AUS:SVC UpdateManager:refreshUpdateStatus - Notifying observers that the update was staged. state: downloading, status: failed: 19
GET http://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/2013/11/2013-11-29-04-02-02-holly/firefox-28.0a1.en-US.win32.complete.mar [HTTP/1.1 200 OK 18089ms]
AUS:SVC Downloader:onStartRequest - original URI spec: http://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/2013/11/2013-11-29-04-02-02-holly/firefox-28.0a1.en-US.win32.complete.mar, final URI spec: http://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/2013/11/2013-11-29-04-02-02-holly/firefox-28.0a1.en-US.win32.complete.mar
AUS:SVC Downloader:onProgress - progress: 13419/36264317
AUS:SVC Downloader:onProgress - progress: 305067/36264317
AUS:SVC Downloader:onProgress - progress: 1405809/36264317
AUS:SVC Downloader:onProgress - progress: 2411553/36264317
AUS:SVC Downloader:onProgress - progress: 3434753/36264317
AUS:SVC Downloader:onProgress - progress: 4445313/36264317
AUS:SVC Downloader:onProgress - progress: 5503505/36264317
AUS:SVC Downloader:onProgress - progress: 6601409/36264317
AUS:SVC Downloader:onProgress - progress: 7708401/36264317
1385744880061	Services.HealthReport.HealthReporter	WARN	No prefs data found.

AUS:SVC Downloader:onProgress - progress: 8780737/36264317
AUS:SVC Downloader:onProgress - progress: 9843317/36264317
AUS:SVC Downloader:onProgress - progress: 10921241/36264317
AUS:SVC Downloader:onProgress - progress: 11974257/36264317
AUS:SVC Downloader:onProgress - progress: 13004361/36264317
AUS:SVC Downloader:onProgress - progress: 14044925/36264317
AUS:SVC Downloader:onProgress - progress: 15041481/36264317
AUS:SVC Downloader:onProgress - progress: 15998401/36264317
AUS:SVC Downloader:onProgress - progress: 17007721/36264317
AUS:SVC Downloader:onProgress - progress: 18082581/36264317
AUS:SVC Downloader:onProgress - progress: 19140241/36264317
AUS:SVC Downloader:onProgress - progress: 20198221/36264317
AUS:SVC Downloader:onProgress - progress: 21237713/36264317
AUS:SVC Downloader:onProgress - progress: 22297297/36264317
AUS:SVC Downloader:onProgress - progress: 23361333/36264317
AUS:SVC Downloader:onProgress - progress: 24389249/36264317
AUS:SVC Downloader:onProgress - progress: 25429501/36264317
AUS:SVC Downloader:onProgress - progress: 26483609/36264317
AUS:SVC Downloader:onProgress - progress: 27507493/36264317
AUS:SVC Downloader:onProgress - progress: 28565237/36264317
AUS:SVC Downloader:onProgress - progress: 29636173/36264317
AUS:SVC Downloader:onProgress - progress: 30682165/36264317
AUS:SVC Downloader:onProgress - progress: 31706365/36264317
AUS:SVC Downloader:onProgress - progress: 32731709/36264317
AUS:SVC Downloader:onProgress - progress: 33757237/36264317
AUS:SVC Downloader:onProgress - progress: 34754401/36264317
AUS:SVC Downloader:onProgress - progress: 35774901/36264317
AUS:SVC Downloader:onProgress - progress: 36264317/36264317
AUS:SVC Downloader:onStopRequest - original URI spec: http://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/2013/11/2013-11-29-04-02-02-holly/firefox-28.0a1.en-US.win32.complete.mar, final URI spec: http://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/2013/11/2013-11-29-04-02-02-holly/firefox-28.0a1.en-US.win32.complete.mar, 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 Downloader:_verifyDownload hashes match.
AUS:SVC Downloader:onStopRequest - setting state to: pending-service
AUS:SVC getCanStageUpdates - able to stage updates because we'll use the service
AUS:SVC Downloader:onStopRequest - attempting to stage update: Holly 28.0a1
AUS:SVC readStatusFile - status: failed: 19, path: C:\Users\mconley\AppData\Local\Mozilla\Firefox\firefox\updates\0\update.status
AUS:SVC handleFallbackToCompleteUpdate - install of complete or only one patch offered failed.
AUS:SVC UpdateManager:refreshUpdateStatus - Notifying observers that the update was staged. state: failed, status: failed: 19


And the Maintenance Service reg entries:
REGEDIT4

[HKEY_LOCAL_MACHINE\SOFTWARE\Mozilla\MaintenanceService]
"Attempted"=dword:00000001
"Installed"=dword:00000001

[HKEY_LOCAL_MACHINE\SOFTWARE\Mozilla\MaintenanceService\105cad4e647fb250cd814fb4fe894222]

[HKEY_LOCAL_MACHINE\SOFTWARE\Mozilla\MaintenanceService\105cad4e647fb250cd814fb4fe894222\0]
"name"="Mozilla Corporation"
"issuer"="Thawte Code Signing CA - G2"

[HKEY_LOCAL_MACHINE\SOFTWARE\Mozilla\MaintenanceService\1121e7121707429fcd2185e3092d7198]

[HKEY_LOCAL_MACHINE\SOFTWARE\Mozilla\MaintenanceService\1121e7121707429fcd2185e3092d7198\0]
"name"="Mozilla Corporation"
"issuer"="Thawte Code Signing CA - G2"

[HKEY_LOCAL_MACHINE\SOFTWARE\Mozilla\MaintenanceService\1b451f129b7b1893d18a9dad544b4651]
"prefetchProcessName"="FIREFOX"

[HKEY_LOCAL_MACHINE\SOFTWARE\Mozilla\MaintenanceService\1b451f129b7b1893d18a9dad544b4651\0]
"name"="Mozilla Corporation"
"issuer"="Thawte Code Signing CA - G2"

[HKEY_LOCAL_MACHINE\SOFTWARE\Mozilla\MaintenanceService\366527286f16f11ca596a3fcfb5e0aa9]
"prefetchProcessName"="FIREFOX"

[HKEY_LOCAL_MACHINE\SOFTWARE\Mozilla\MaintenanceService\366527286f16f11ca596a3fcfb5e0aa9\0]
"name"="Mozilla Corporation"
"issuer"="DigiCert Assured ID Code Signing CA-1"

[HKEY_LOCAL_MACHINE\SOFTWARE\Mozilla\MaintenanceService\4490fff58b86e758cba5a0ed70f1689a]

[HKEY_LOCAL_MACHINE\SOFTWARE\Mozilla\MaintenanceService\4490fff58b86e758cba5a0ed70f1689a\0]
"name"="Mozilla Corporation"
"issuer"="Thawte Code Signing CA - G2"

[HKEY_LOCAL_MACHINE\SOFTWARE\Mozilla\MaintenanceService\965b7fc26dad90d340d2fa0a4879039f]
"prefetchProcessName"="FIREFOX"

[HKEY_LOCAL_MACHINE\SOFTWARE\Mozilla\MaintenanceService\965b7fc26dad90d340d2fa0a4879039f\0]
"name"="Mozilla Corporation"
"issuer"="DigiCert Assured ID Code Signing CA-1"

[HKEY_LOCAL_MACHINE\SOFTWARE\Mozilla\MaintenanceService\a4948786b022cc1a376991b44efb838c]
"prefetchProcessName"="FIREFOX"

[HKEY_LOCAL_MACHINE\SOFTWARE\Mozilla\MaintenanceService\a4948786b022cc1a376991b44efb838c\0]
"name"="Mozilla Corporation"
"issuer"="Thawte Code Signing CA - G2"

[HKEY_LOCAL_MACHINE\SOFTWARE\Mozilla\MaintenanceService\a9c43fa11967f504f6ba297e13fd2de3]
"prefetchProcessName"="FIREFOX"

[HKEY_LOCAL_MACHINE\SOFTWARE\Mozilla\MaintenanceService\a9c43fa11967f504f6ba297e13fd2de3\0]
"name"="Mozilla Corporation"
"issuer"="DigiCert Assured ID Code Signing CA-1"

[HKEY_LOCAL_MACHINE\SOFTWARE\Mozilla\MaintenanceService\b4a1b97c55560f4844c6414f020ba6f6]

[HKEY_LOCAL_MACHINE\SOFTWARE\Mozilla\MaintenanceService\b4a1b97c55560f4844c6414f020ba6f6\0]
"name"="Mozilla Corporation"
"issuer"="Thawte Code Signing CA - G2"

Brian, I originally thought this might be some case of the maintenance service having missing entries, but it doesn't seem to be the case. Rail and I confirmed that mozilla-central and Holly are both getting signed by the same MAR signing key - any idea what's happening here?

Comment 2

[Brian R. Bondy [:bbondy]]

Ya this is a MAR verification error, so it sounds like something is wrong with the MAR file. This isn't related to the authenticode binary signing but related to the MAR signing.  Maybe the MAR wasn't signed at all?

Comment 3

[Brian R. Bondy [:bbondy]]

Or perhaps the MAR is corrupted in some way? Maybe a new nightly spin would fix?

Comment 4

[[e-mail] (:bhearsum)]

(In reply to Brian R. Bondy [:bbondy] from comment #2)
> Ya this is a MAR verification error, so it sounds like something is wrong
> with the MAR file. This isn't related to the authenticode binary signing but
> related to the MAR signing.  Maybe the MAR wasn't signed at all?

Oh, right. I forgot that the maintenance service reg entries were related to authenticode signatures.

Comment 5

[[e-mail] (:bhearsum)]

The MAR is definitely getting signed:
c:\builds\moz2_slave\h-w32-ntly-0000000000000000000\build\obj-firefox\tools\update-packaging\Makefile:74:0$ python c:/builds/moz2_slave/h-w32-ntly-0000000000000000000/tools/release/signing/signtool.py --cachedir c:/builds/moz2_slave/h-w32-ntly-0000000000000000000/signing_cache -t c:/builds/moz2_slave/h-w32-ntly-0000000000000000000/token -n c:/builds/moz2_slave/h-w32-ntly-0000000000000000000/nonce -c c:/builds/moz2_slave/h-w32-ntly-0000000000000000000/tools/release/signing/host.cert -H signing4.srv.releng.scl3.mozilla.com:9100 -H signing5.srv.releng.scl3.mozilla.com:9100 -H signing6.srv.releng.scl3.mozilla.com:9100 -f mar "../../dist/update//firefox-28.0a1.en-US.win32.complete.mar"

Finished
2013-11-29 06:53:14,927 - 36107f393e701dd0896f284059ff0829497631bd: processing ../../dist/update//firefox-28.0a1.en-US.win32.complete.mar on https://signing5.srv.releng.scl3.mozilla.com:9100
2013-11-29 06:53:15,187 - 36107f393e701dd0896f284059ff0829497631bd: uploading for signing
2013-11-29 06:53:29,039 - 36107f393e701dd0896f284059ff0829497631bd: processing ../../dist/update//firefox-28.0a1.en-US.win32.complete.mar on https://signing5.srv.releng.scl3.mozilla.com:9100
2013-11-29 06:53:32,568 - 36107f393e701dd0896f284059ff0829497631bd: OK

And that signing server instance is a Nightly instance.

Mike, can you paste your update-settings.ini?

Comment 6

[[e-mail] (:bhearsum)]

> Mike, can you paste your update-settings.ini?

Whoops, meant to needinfo

Comment 7

[Mike Conley (:mconley) (:⚙️)]

; If you modify this file updates may fail.
; Do not modify this file.

[Settings]
ACCEPTED_MAR_CHANNEL_IDS=firefox-mozilla-central

Comment 8

[[e-mail] (:bhearsum)]

Fix incoming:
14:44 < bbondy> bhearsum: I think we probably wanted holly here: 
http://dxr.mozilla.org/mozilla-central/source/toolkit/mozapps/update/updater/Makefile.in#102
14:44 < bhearsum> ah, indeed
14:44 < bhearsum> it's embedding the dep certs
14:44 < bhearsum> OK
14:44 < bbondy> so it's going to get signed with...
14:44 < bbondy> yep
14:45 < bhearsum> not the end of the world - i'll fix that, and the next set of 
                  nightlies will apply fine

Comment 9

[[e-mail] (:bhearsum)]

Attachment: enable nightly certificates for holly

Comment 10

[[e-mail] (:bhearsum)]

Comment on attachment 8340522 [details] [diff] [review]
enable nightly certificates for holly

I landed this. The next set of nightlies (which spin around 3am tomorrow morning) should have working updates. Leaving this open to confirm.

Comment 11

[u52928]

I've been having same problem on  XP SP3. Problem was not fixed in update from 29->30 Nov.

Comment 12

[Nick Thomas [:nthomas] (UTC+12)]

I think it will work if you have the Nov 30 nightly [1], and update when a later nightly is available (there isn't one just yet).

AIUI, builds from before Nov 30 have an updater.exe that's expecting a mar file signed with the development certificate, but the mar file is actually signed with the nightly cert. From Nov 30 the updater.exe expects nightly certs.

Releng, we probably should write ourselves a howto for enabling nightly updates on project branches. See also bug 906466.

[1] http://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/2013/11/2013-11-30-04-02-00-holly/

Comment 13

[[e-mail] (:bhearsum)]

(In reply to Nick Thomas [:nthomas] from comment #12)
> I think it will work if you have the Nov 30 nightly [1], and update when a
> later nightly is available (there isn't one just yet).
> 
> AIUI, builds from before Nov 30 have an updater.exe that's expecting a mar
> file signed with the development certificate, but the mar file is actually
> signed with the nightly cert. From Nov 30 the updater.exe expects nightly
> certs.

Oh, shoot, good point. Pentaho only shows 35 people on holly builds prior to the 30th...so I'm not going to go to the trouble of creating a custom update to fix them up.

> Releng, we probably should write ourselves a howto for enabling nightly
> updates on project branches. See also bug 906466.

+1. I filed https://bugzilla.mozilla.org/show_bug.cgi?id=945242 for this.

I think this particular bug is FIXED now?