Closed Bug 1574404 Opened Last month Closed Last month

Nightly fails to update, both partial and full mar downloads generate errors

Categories

(Release Engineering :: Release Automation: Updates, defect, P1)

defect

Tracking

(Not tracked)

RESOLVED DUPLICATE of bug 1537710

People

(Reporter: Pike, Unassigned)

References

Details

(Whiteboard: [releaseduty])

Here's what I have in my update logs:

AUS:SVC Creating Downloader
AUS:SVC UpdateService:_downloadUpdate
AUS:SVC readStringFromFile - file doesn't exist: /Users/axelhecht/Library/Caches/Mozilla/updates/Applications/Firefox Nightly/updates/0/update.status
AUS:SVC readStatusFile - status: null, path: /Users/axelhecht/Library/Caches/Mozilla/updates/Applications/Firefox Nightly/updates/0/update.status
AUS:SVC getCanUseBits - Not using BITS because this is not Windows
AUS:SVC Downloader:downloadUpdate - Starting nsIIncrementalDownload with url: https://archive.mozilla.org/pub/firefox/nightly/partials/2019/08/2019-08-15-19-35-05-mozilla-central-l10n/firefox-mozilla-central-70.0a1-mac-de-20190815094649-20190815193505.partial.mar, path: /Users/axelhecht/Library/Caches/Mozilla/updates/Applications/Firefox Nightly/updates/0/update.mar, interval: 0
AUS:SVC Downloader:onStartRequest - original URI spec: https://archive.mozilla.org/pub/firefox/nightly/partials/2019/08/2019-08-15-19-35-05-mozilla-central-l10n/firefox-mozilla-central-70.0a1-mac-de-20190815094649-20190815193505.partial.mar, final URI spec: https://archive.mozilla.org/pub/firefox/nightly/partials/2019/08/2019-08-15-19-35-05-mozilla-central-l10n/firefox-mozilla-central-70.0a1-mac-de-20190815094649-20190815193505.partial.mar
AUS:SVC Downloader:onProgress - progress: 14480/6766480
AUS:SVC Downloader:onProgress - maxProgress: 6766480 is not equal to expected patch size: 6759312
AUS:SVC Downloader: cancel
AUS:SVC Downloader:onProgress - progress: 0/6766480
AUS:SVC Downloader:onStopRequest - downloader: nsIIncrementalDownload, original URI spec: https://archive.mozilla.org/pub/firefox/nightly/partials/2019/08/2019-08-15-19-35-05-mozilla-central-l10n/firefox-mozilla-central-70.0a1-mac-de-20190815094649-20190815193505.partial.mar, final URI spec: https://archive.mozilla.org/pub/firefox/nightly/partials/2019/08/2019-08-15-19-35-05-mozilla-central-l10n/firefox-mozilla-central-70.0a1-mac-de-20190815094649-20190815193505.partial.mar, status: 2147549183
AUS:SVC Downloader:onStopRequest - status: 2147549183, current fail: 0, max fail: 10, retryTimeout: 2000
AUS:SVC Downloader:onStopRequest - non-verification failure
AUS:SVC getStatusTextFromCode - transfer error: Fehlgeschlagen (Unbekannter Grund), default code: 2152398849
AUS:SVC Downloader:onStopRequest - setting state to: download-failed
AUS:SVC Downloader:onStopRequest - verification of patch failed, downloading complete update patch
AUS:SVC UpdateService:_downloadUpdate
AUS:SVC readStringFromFile - file doesn't exist: /Users/axelhecht/Library/Caches/Mozilla/updates/Applications/Firefox Nightly/updates/0/update.status
AUS:SVC readStatusFile - status: null, path: /Users/axelhecht/Library/Caches/Mozilla/updates/Applications/Firefox Nightly/updates/0/update.status
AUS:SVC Downloader:_selectPatch - found existing patch with state: null
AUS:SVC getCanUseBits - Not using BITS because this is not Windows
AUS:SVC Downloader:downloadUpdate - Starting nsIIncrementalDownload with url: https://archive.mozilla.org/pub/firefox/nightly/2019/08/2019-08-15-19-35-05-mozilla-central-l10n/firefox-70.0a1.de.mac.complete.mar, path: /Users/axelhecht/Library/Caches/Mozilla/updates/Applications/Firefox Nightly/updates/0/update.mar, interval: 0
AUS:SVC Downloader:onStartRequest - original URI spec: https://archive.mozilla.org/pub/firefox/nightly/2019/08/2019-08-15-19-35-05-mozilla-central-l10n/firefox-70.0a1.de.mac.complete.mar, final URI spec: https://archive.mozilla.org/pub/firefox/nightly/2019/08/2019-08-15-19-35-05-mozilla-central-l10n/firefox-70.0a1.de.mac.complete.mar
AUS:SVC Downloader:onProgress - progress: 16905/63383227
AUS:SVC Downloader:onProgress - maxProgress: 63383227 is not equal to expected patch size: 63383163
AUS:SVC Downloader: cancel
AUS:SVC Downloader:onProgress - progress: 0/63383227
AUS:SVC Downloader:onStopRequest - downloader: nsIIncrementalDownload, original URI spec: https://archive.mozilla.org/pub/firefox/nightly/2019/08/2019-08-15-19-35-05-mozilla-central-l10n/firefox-70.0a1.de.mac.complete.mar, final URI spec: https://archive.mozilla.org/pub/firefox/nightly/2019/08/2019-08-15-19-35-05-mozilla-central-l10n/firefox-70.0a1.de.mac.complete.mar, status: 2147549183
AUS:SVC Downloader:onStopRequest - status: 2147549183, current fail: 0, max fail: 10, retryTimeout: 2000
AUS:SVC Downloader:onStopRequest - non-verification failure
AUS:SVC getStatusTextFromCode - transfer error: Fehlgeschlagen (Unbekannter Grund), default code: 2152398849
AUS:SVC Downloader:onStopRequest - setting state to: download-failed
AUS:SVC Downloader:onStopRequest - notifying observers of error. topic: update-error, status: download-attempts-exceeded, downloadAttempts: 5 maxAttempts: 2
AUS:SVC UpdateManager:_writeUpdatesToXMLFile - no updates to write. removing file: /Users/axelhecht/Library/Caches/Mozilla/updates/Applications/Firefox Nightly/active-update.xml
AUS:SVC Checker: checkForUpdates, force: true
AUS:SVC UpdateService.canCheckForUpdates - able to check for updates
AUS:SVC Checker:getUpdateURL - update URL: https://aus5.mozilla.org/update/6/Firefox/70.0a1/20190815094649/Darwin_x86_64-gcc3/de/nightly/Darwin%2018.7.0/ISET:SSE4_2,MEM:32768/default/default/update.xml?force=1
AUS:SVC Checker:checkForUpdates - sending request to: https://aus5.mozilla.org/update/6/Firefox/70.0a1/20190815094649/Darwin_x86_64-gcc3/de/nightly/Darwin%2018.7.0/ISET:SSE4_2,MEM:32768/default/default/update.xml?force=1
OpenGL compositor Initialized Succesfully.
Version: 2.1 ATI-2.11.20
Vendor: ATI Technologies Inc.
Renderer: AMD Radeon Pro 560X OpenGL Engine
FBO Texture Target: TEXTURE_2D
AUS:SVC Checker:onLoad - request completed downloading document
AUS:SVC Checker:onLoad - Getting sslStatus failed.
AUS:SVC Checker:onLoad - number of updates available: 1
AUS:SVC getElevationRequired - recursively testing write access on /Applications/Firefox Nightly.app
AUS:SVC getElevationRequired - able to write to application bundle, elevation not required
AUS:SVC getCanApplyUpdates - testing write access /Users/axelhecht/Library/Caches/Mozilla/updates/Applications/Firefox Nightly/update.test
AUS:SVC getCanApplyUpdates - bypass the write since elevation can be used on Mac OS X
AUS:SVC Creating Downloader
AUS:SVC UpdateService:_downloadUpdate
AUS:SVC readStringFromFile - file doesn't exist: /Users/axelhecht/Library/Caches/Mozilla/updates/Applications/Firefox Nightly/updates/0/update.status
AUS:SVC readStatusFile - status: null, path: /Users/axelhecht/Library/Caches/Mozilla/updates/Applications/Firefox Nightly/updates/0/update.status
AUS:SVC getCanUseBits - Not using BITS because this is not Windows
AUS:SVC Downloader:downloadUpdate - Starting nsIIncrementalDownload with url: https://archive.mozilla.org/pub/firefox/nightly/partials/2019/08/2019-08-15-19-35-05-mozilla-central-l10n/firefox-mozilla-central-70.0a1-mac-de-20190815094649-20190815193505.partial.mar, path: /Users/axelhecht/Library/Caches/Mozilla/updates/Applications/Firefox Nightly/updates/0/update.mar, interval: 0
AUS:SVC Downloader:onStartRequest - original URI spec: https://archive.mozilla.org/pub/firefox/nightly/partials/2019/08/2019-08-15-19-35-05-mozilla-central-l10n/firefox-mozilla-central-70.0a1-mac-de-20190815094649-20190815193505.partial.mar, final URI spec: https://archive.mozilla.org/pub/firefox/nightly/partials/2019/08/2019-08-15-19-35-05-mozilla-central-l10n/firefox-mozilla-central-70.0a1-mac-de-20190815094649-20190815193505.partial.mar
AUS:SVC Downloader:onProgress - progress: 14480/6766480
AUS:SVC Downloader:onProgress - maxProgress: 6766480 is not equal to expected patch size: 6759312
AUS:SVC Downloader: cancel
AUS:SVC Downloader:onProgress - progress: 0/6766480
AUS:SVC Downloader:onStopRequest - downloader: nsIIncrementalDownload, original URI spec: https://archive.mozilla.org/pub/firefox/nightly/partials/2019/08/2019-08-15-19-35-05-mozilla-central-l10n/firefox-mozilla-central-70.0a1-mac-de-20190815094649-20190815193505.partial.mar, final URI spec: https://archive.mozilla.org/pub/firefox/nightly/partials/2019/08/2019-08-15-19-35-05-mozilla-central-l10n/firefox-mozilla-central-70.0a1-mac-de-20190815094649-20190815193505.partial.mar, status: 2147549183
AUS:SVC Downloader:onStopRequest - status: 2147549183, current fail: 0, max fail: 10, retryTimeout: 2000
AUS:SVC Downloader:onStopRequest - non-verification failure
AUS:SVC getStatusTextFromCode - transfer error: Fehlgeschlagen (Unbekannter Grund), default code: 2152398849
AUS:SVC Downloader:onStopRequest - setting state to: download-failed
AUS:SVC Downloader:onStopRequest - verification of patch failed, downloading complete update patch
AUS:SVC UpdateService:_downloadUpdate
AUS:SVC readStringFromFile - file doesn't exist: /Users/axelhecht/Library/Caches/Mozilla/updates/Applications/Firefox Nightly/updates/0/update.status
AUS:SVC readStatusFile - status: null, path: /Users/axelhecht/Library/Caches/Mozilla/updates/Applications/Firefox Nightly/updates/0/update.status
AUS:SVC Downloader:_selectPatch - found existing patch with state: null
AUS:SVC getCanUseBits - Not using BITS because this is not Windows
AUS:SVC Downloader:downloadUpdate - Starting nsIIncrementalDownload with url: https://archive.mozilla.org/pub/firefox/nightly/2019/08/2019-08-15-19-35-05-mozilla-central-l10n/firefox-70.0a1.de.mac.complete.mar, path: /Users/axelhecht/Library/Caches/Mozilla/updates/Applications/Firefox Nightly/updates/0/update.mar, interval: 0
AUS:SVC Downloader:onStartRequest - original URI spec: https://archive.mozilla.org/pub/firefox/nightly/2019/08/2019-08-15-19-35-05-mozilla-central-l10n/firefox-70.0a1.de.mac.complete.mar, final URI spec: https://archive.mozilla.org/pub/firefox/nightly/2019/08/2019-08-15-19-35-05-mozilla-central-l10n/firefox-70.0a1.de.mac.complete.mar
AUS:SVC Downloader:onProgress - progress: 16905/63383227
AUS:SVC Downloader:onProgress - maxProgress: 63383227 is not equal to expected patch size: 63383163
AUS:SVC Downloader: cancel
AUS:SVC Downloader:onProgress - progress: 0/63383227
AUS:SVC Downloader:onStopRequest - downloader: nsIIncrementalDownload, original URI spec: https://archive.mozilla.org/pub/firefox/nightly/2019/08/2019-08-15-19-35-05-mozilla-central-l10n/firefox-70.0a1.de.mac.complete.mar, final URI spec: https://archive.mozilla.org/pub/firefox/nightly/2019/08/2019-08-15-19-35-05-mozilla-central-l10n/firefox-70.0a1.de.mac.complete.mar, status: 2147549183
AUS:SVC Downloader:onStopRequest - status: 2147549183, current fail: 0, max fail: 10, retryTimeout: 2000
AUS:SVC Downloader:onStopRequest - non-verification failure
AUS:SVC getStatusTextFromCode - transfer error: Fehlgeschlagen (Unbekannter Grund), default code: 2152398849
AUS:SVC Downloader:onStopRequest - setting state to: download-failed
AUS:SVC Downloader:onStopRequest - notifying observers of error. topic: update-error, status: download-attempts-exceeded, downloadAttempts: 6 maxAttempts: 2
AUS:SVC UpdateManager:_writeUpdatesToXMLFile - no updates to write. removing file: /Users/axelhecht/Library/Caches/Mozilla/updates/Applications/Firefox Nightly/active-update.xml

Mihai, can you investigate what's wrong here? Common issue reported in #developers. Thank you.

Flags: needinfo?(mtabara)

Looks like we have two builds off the same revision?

$ curl -s https://aus-api.mozilla.org/api/v1/releases/Firefox-mozilla-central-nightly-20190815193505 | jq '.platforms."Darwin_x86_64-gcc3-u-i386-x86_64".locales.de.completes'
[
  {
    "fileUrl": "https://archive.mozilla.org/pub/firefox/nightly/2019/08/2019-08-15-19-35-05-mozilla-central-l10n/firefox-70.0a1.de.mac.complete.mar",
    "filesize": 63383163,
    "from": "*",
    "hashValue": "c5dba983e76bf717c5b21f6137af3368a0afd5ca2add5fac7444f7ee354d6451ac3ea63ca3e930922f3be82e6ff6086b78524ad602681727d855197fab623e0c"
  },
  {
    "fileUrl": "https://archive.mozilla.org/pub/firefox/nightly/2019/08/2019-08-15-19-35-05-mozilla-central-l10n/firefox-70.0a1.de.mac.complete.mar",
    "filesize": 63383227,
    "from": "*",
    "hashValue": "823460fc7b3622f98abac6a285054cdd55c3db785d070ed4f188a986b1bab73c59164885d661fd2c51826198c4e2130b22eb2d1b4b01f7cea306c9e07ee7a7b6"
  }
]

Confirming I also see this in my update log.

Flags: needinfo?(mtabara)
Whiteboard: [releaseduty]
Priority: -- → P1

Turns out we had two nightlies triggered last night, based on the same revision. For some reason I recall we've hit this before.
It's https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&searchStr=nightly&revision=b283a7ef186c216d765631f6cb1260a3fa2ee42c

At 2019-08-15T19:45:20.912Z, the first decision task was triggered - https://tools.taskcluster.net/groups/c9bVskeaT5Os0Uy7IJ7ZxA/tasks/c9bVskeaT5Os0Uy7IJ7ZxA/details

At 2019-08-15T22:00:26.923Z, the second decision task was triggered - https://tools.taskcluster.net/groups/dlzpxOqnTxGRm5l0aBLkxw/tasks/dlzpxOqnTxGRm5l0aBLkxw/details

Since the revision 283a7ef186cCNMerge was a "inbound to mozilla-central. a=merge", I'm tempted to believe that someone manually triggered the nightlies. Then, 2h15min later, the cron job automatically triggered and since there was no other revision pushed in between, it triggered it again, based on the same revision.

Questions:

  • for some reason I recall hitting this bug in the past, I'll dig to see what was the resolution back then.
  • how come no tasks complained along the way? balrog should prevent updating blob if it's already updated, beetmover shouldn't overwrite, bouncer locations should've failed

(In reply to Mihai Tabara [:mtabara]⌚️GMT from comment #4)

Questions:

  • how come no tasks complained along the way? balrog should prevent updating blob if it's already updated, beetmover shouldn't overwrite, bouncer locations should've failed

Hm, at second thoughts:

  • beetmover is expected to overwrite, it's in its design since BB -> TC migration work
  • bouncer locations didn't complain because the version is the same and it simply no-op, like all other jobs during the normal cycle
  • balrog didn't complain because it's likely the "download/merge json" behavior. I wonder if we should be more cautios here.

Another solution could be to change the cron job to double-check if there's another decision task for that revision. This has the downside of not being able to actually rerun the decision task if we really need to, at one point.

Status: NEW → RESOLVED
Closed: Last month
Resolution: --- → DUPLICATE
Duplicate of bug: 1537710
You need to log in before you can comment on or make changes to this bug.