Closed Bug 1454563 Opened 2 years ago Closed 2 years ago

Intermittent AddonInstallException: Could not install add-on at '/tmp/tmp7Fhtav.zip': UnknownError: ERROR_CORRUPT_FILE: The file appears to be corrupt.

Categories

(Toolkit :: Add-ons Manager, defect, P5)

defect

Tracking

()

RESOLVED FIXED
mozilla61
Tracking Status
firefox-esr52 --- unaffected
firefox59 --- unaffected
firefox60 --- unaffected
firefox61 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: Gijs)

References

Details

(Keywords: intermittent-failure, regression)

Attachments

(1 file)

Filed by: nbeleuzu [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=173972342&repo=autoland

https://queue.taskcluster.net/v1/task/XcX7osbdRvC6vdnVo7gfgg/runs/0/artifacts/public/logs/live_backing.log

Relevant log info:

[task 2018-04-16T21:36:11.904Z] 21:36:11     INFO -      raise AddonInstallException(e)
[task 2018-04-16T21:36:11.905Z] 21:36:11     INFO -  AddonInstallException: Could not install add-on at '/tmp/tmp7Fhtav.zip': UnknownError: ERROR_CORRUPT_FILE: The file appears to be corrupt.
[task 2018-04-16T21:36:11.905Z] 21:36:11     INFO -  stacktrace:
[task 2018-04-16T21:36:11.909Z] 21:36:11     INFO -  	WebDriverError@chrome://marionette/content/error.js:178:5
[task 2018-04-16T21:36:11.912Z] 21:36:11     INFO -  	UnknownError@chrome://marionette/content/error.js:483:5
[task 2018-04-16T21:36:11.912Z] 21:36:11     INFO -  	addon.install@chrome://marionette/content/addon.js:109:11
[task 2018-04-16T21:36:11.915Z] 21:36:11     INFO -  	async*GeckoDriver.prototype.installAddon@chrome://marionette/content/driver.js:3299:10
[task 2018-04-16T21:36:11.915Z] 21:36:11     INFO -  	despatch@chrome://marionette/content/server.js:293:20
[task 2018-04-16T21:36:11.915Z] 21:36:11     INFO -  	async*execute@chrome://marionette/content/server.js:267:11
[task 2018-04-16T21:36:11.918Z] 21:36:11     INFO -  	async*onPacket/<@chrome://marionette/content/server.js:242:15
[task 2018-04-16T21:36:11.919Z] 21:36:11     INFO -  	async*onPacket@chrome://marionette/content/server.js:241:8
[task 2018-04-16T21:36:11.920Z] 21:36:11     INFO -  	_onJSONObjectReady/<@chrome://marionette/content/transport.js:500:9
[task 2018-04-16T21:36:11.920Z] 21:36:11    ERROR - Automation Error: Received unexpected exception while running application
[task 2018-04-16T21:36:11.922Z] 21:36:11    ERROR - 
[task 2018-04-16T21:36:11.922Z] 21:36:11     INFO - Stopping web server
[task 2018-04-16T21:36:11.923Z] 21:36:11     INFO - GECKO(6348) | 1523914571888	addons.xpi	WARN	Invalid XPI: TypeError: aAddonEntries is null (jar:file:///builds/worker/workspace/build/application/firefox/omni.ja!/components/nsBlocklistService.js:421:1) JS Stack trace: _findMatchingAddonEntry@nsBlocklistService.js:421:1
Component: Developer Tools: Debugger → Add-ons Manager
Product: Firefox → Toolkit
Summary: Intermittent Automation Error: Received unexpected exception while running application → Intermittent AddonInstallException: Could not install add-on at '/tmp/tmp7Fhtav.zip': UnknownError: ERROR_CORRUPT_FILE: The file appears to be corrupt.
Gijs, I didn't follow bug 1447680 very closely, could this be fallout from that change?  I see a bunch of blocklist related errors in the log.
If you've had enough of the blocklist for the week/month/whatever I can dig into this...
Flags: needinfo?(gijskruitbosch+bugs)
(In reply to Andrew Swan [:aswan] from comment #1)
> Gijs, I didn't follow bug 1447680 very closely, could this be fallout from
> that change?  I see a bunch of blocklist related errors in the log.
> If you've had enough of the blocklist for the week/month/whatever I can dig
> into this...

It's definitely a blocklist issue. The issue seems to be that it manages to hit a case where the blocklist loading promise is resolved, but `this._addonEntries` is null.

This was also the cause of the android failures when I originally landed bug 1452618. The android failures were fixed by making `_loadBlocklistAsyncInternal()` set all the `*entries` properties to empty arrays if both loading the profile and loading the appdir blocklist.xml file failed.

I don't really understand why this would be the case again here. Looking at the code at https://hg.mozilla.org/mozilla-central/file/tip/toolkit/mozapps/extensions/nsBlocklistService.js#l771, _addonEntries should always at least be an empty array if loading things failed, unless we're somehow catching an error but returning early without setting any of these properties, or something?


[task 2018-04-16T21:36:09.678Z] 21:36:09     INFO - GECKO(6348) | 1523914569672	addons.manager	WARN	Failed to copy the application shipped blocklist to the profile: [Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIFile.copyTo]"  nsresult: "0x80004005 (NS_ERROR_FAILURE)"  location: "JS frame :: resource://gre/modules/AddonManager.jsm :: validateBlocklist :: line 640"  data: no] Stack trace: validateBlocklist()@resource://gre/modules/AddonManager.jsm:640
[task 2018-04-16T21:36:09.678Z] 21:36:09     INFO - GECKO(6348) | startup()@resource://gre/modules/AddonManager.jsm:795
[task 2018-04-16T21:36:09.679Z] 21:36:09     INFO - GECKO(6348) | startup()@resource://gre/modules/AddonManager.jsm:2919
[task 2018-04-16T21:36:09.679Z] 21:36:09     INFO - GECKO(6348) | observe()@jar:file:///builds/worker/workspace/build/application/firefox/omni.ja!/components/addonManager.js:63

looks relevant.

It does look like we could return early if the blocklist was entirely disabled (and we should probably fix that...), but then I'd expect this to either fail all the time or fail none of the time, not intermittently... and in any case, there's also an early return for that in _getAddonBlocklistEntry so that's not causing this.
Blocks: 1452618
I wonder if this is really correlated with that validateBlocklist thing... I don't see that being logged anywhere else in the same mochitest job (it has earlier successful test runs). Maybe there's a race of sorts if both that (which does sync mainthread IO, whee!) and the async read of the blocklist happen at the same time, or something?

Andrew/Kris, do you see any other obvious clues as to what might go wrong? Or am I missing something in my reading in comment #2, maybe?
Flags: needinfo?(kmaglione+bmo)
Flags: needinfo?(aswan)
When the file exists, but _loadBlocklistFromString fails to parse it, we return from _loadBlocklistAsyncInternal but don't actually ever get to _loadBlocklistFromXML.

In automation, we tend to write out empty blocklist files. Some of them might be invalid.
Flags: needinfo?(kmaglione+bmo)
After wasting more time than I'd like to admit looking at out of date code on searchfox, I think Kris has it right in comment 4.
Flags: needinfo?(aswan)
(In reply to Kris Maglione [:kmag] (long backlog; ping on IRC if you're blocked) from comment #4)
> When the file exists, but _loadBlocklistFromString fails to parse it, we
> return from _loadBlocklistAsyncInternal but don't actually ever get to
> _loadBlocklistFromXML.
> 
> In automation, we tend to write out empty blocklist files. Some of them
> might be invalid.

D'oh, of course. Thanks for the hand-holding.
Flags: needinfo?(gijskruitbosch+bugs)
Assignee: nobody → gijskruitbosch+bugs
Status: NEW → ASSIGNED
Comment on attachment 8968690 [details]
Bug 1454563 - actually add real fallback from profile to appdir blocklist if loading the profile one fails,

https://reviewboard.mozilla.org/r/237370/#review243188

Thanks

::: toolkit/mozapps/extensions/nsBlocklistService.js:819
(Diff revision 1)
>      }
>  
>      let text = await OS.File.read(path, { encoding: "utf-8" });
>  
> -    await new Promise(resolve => {
> +    await new Promise((resolve, reject) => {
>        Services.tm.idleDispatchToMainThread(() => {

While you're here, can you make this `ChromeUtils.idleDispatch`?
Attachment #8968690 - Flags: review?(kmaglione+bmo) → review+
Pushed by gijskruitbosch@gmail.com:
https://hg.mozilla.org/integration/autoland/rev/c513037dd551
actually add real fallback from profile to appdir blocklist if loading the profile one fails, r=kmag
https://hg.mozilla.org/mozilla-central/rev/c513037dd551
Status: ASSIGNED → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla61
Is manual testing required on this bug? If Yes, please provide some STR and the proper webextension(if required), if No set the “qe-verify-“ flag.
Flags: needinfo?(gijskruitbosch+bugs)
(In reply to marius.santa from comment #13)
> Is manual testing required on this bug? If Yes, please provide some STR and
> the proper webextension(if required), if No set the “qe-verify-“ flag.

We never need manual testing on intermittent-failure bugs.
Flags: needinfo?(gijskruitbosch+bugs) → qe-verify-
You need to log in before you can comment on or make changes to this bug.