Closed Bug 1313960 Opened 3 years ago Closed 3 years ago

Exception calling provider XPIProvider.addonChanged on Dev Edition theme

Categories

(Toolkit :: Add-ons Manager, defect, P3, minor)

52 Branch
defect

Tracking

()

RESOLVED FIXED
mozilla53
Tracking Status
firefox53 --- fixed

People

(Reporter: euthanasia_waltz, Assigned: rhelmer)

References

Details

(Whiteboard: triaged)

Attachments

(1 file)

By selecting Developer Edition theme, an error is logged in Browser Console when starting firefox. (I don't know real problems caused by this error though.)
---
1477867064495	addons.manager	ERROR	Exception calling provider XPIProvider.addonChanged: TypeError: this._dbPromise.resolve is not a function (resource://gre/modules/addons/XPIProvider.jsm -> resource://gre/modules/addons/XPIProviderUtils.js:626:7) JS Stack trace: this.XPIDatabase.syncLoadDB@XPIProviderUtils.js:626:7 < this.XPIDatabase.getAddonsByType@XPIProviderUtils.js:1204:7 < this.XPIProvider.addonChanged@XPIProvider.jsm:4369:18 < callProvider@AddonManager.jsm:236:12 < AddonManagerInternal.notifyAddonChanged@AddonManager.jsm:1807:7 < this.AddonManagerPrivate.notifyAddonChanged@AddonManager.jsm:3072:5 < _setCurrentTheme@LightweightThemeManager.jsm:709:3 < set currentTheme@LightweightThemeManager.jsm:148:12 < this.LightweightThemeManager.addBuiltInTheme@LightweightThemeManager.jsm:190:7 < BG__finalUIStartup@nsBrowserGlue.js:707:7 < BG_observe@nsBrowserGlue.js:191:9
---
(Build 52.0a1/20161030030204)

mozregression:
10:40.05 INFO: Last good revision: 14277a31e124303c85890f363b31f12dab245f72
10:40.05 INFO: First bad revision: 41a2caef2b66d3dca1debe1ac5b4fea58d0fe6f5
10:40.05 INFO: Pushlog:
https://hg.mozilla.org/integration/mozilla-inbound/pushloghtml?fromchange=14277a31e124303c85890f363b31f12dab245f72&tochange=41a2caef2b66d3dca1debe1ac5b4fea58d0fe6f5

10:40.92 INFO: Looks like the following bug has the changes which introduced the regression:
https://bugzilla.mozilla.org/show_bug.cgi?id=1164954
Blocks: 1164954
Looks like this is exposing broken code in the XPIProvider.

https://dxr.mozilla.org/mozilla-central/source/toolkit/mozapps/extensions/internal/XPIProviderUtils.js#622-626

    // If an async load was also in progress, resolve that promise with our DB;
    // otherwise create a resolved promise
    if (this._dbPromise) {
      AddonManagerPrivate.recordSimpleMeasure("XPIDB_overlapped_load", 1);
      this._dbPromise.resolve(this.addonDB);
    }

_dbPromise is a 'real' promise, and so it doesn't have a resolve method. This needs a bunch of juggling about to actually fix. AFAICT this was broken since bug 853388, though maybe OS.File used to use promises that did expose those methods and now doesn't, or something?

I also don't see code that prevents this from resolving twice if this code even worked, which would also need fixing...

However, it also sounds like the changes in bug 1164954 are forcing sync reading of the db (hopefully only if the builtin devedition theme is selected on startup). That doesn't sound very good, but looking at the above code maybe we can check with telemetry or something. Dave?
Flags: needinfo?(dtownsend)
(In reply to :Gijs Kruitbosch from comment #1)
> However, it also sounds like the changes in bug 1164954 are forcing sync
> reading of the db (hopefully only if the builtin devedition theme is
> selected on startup). That doesn't sound very good, but looking at the above
> code maybe we can check with telemetry or something. Dave?

Yeah, sync reading is bad. Is that happening of every startup? If so ... bad! I don't know what we have in telemetry anymore so maybe Rob should dig in here.
Flags: needinfo?(dtownsend) → needinfo?(rhelmer)
Assignee: nobody → rhelmer
Status: UNCONFIRMED → ASSIGNED
Ever confirmed: true
Flags: needinfo?(rhelmer)
(In reply to atlanto from comment #0)
> By selecting Developer Edition theme, an error is logged in Browser Console
> when starting firefox. (I don't know real problems caused by this error
> though.)
> ---
> 1477867064495	addons.manager	ERROR	Exception calling provider
> XPIProvider.addonChanged: TypeError: this._dbPromise.resolve is not a
> function (resource://gre/modules/addons/XPIProvider.jsm ->
> resource://gre/modules/addons/XPIProviderUtils.js:626:7) JS Stack trace:
> this.XPIDatabase.syncLoadDB@XPIProviderUtils.js:626:7 <
> this.XPIDatabase.getAddonsByType@XPIProviderUtils.js:1204:7 <
> this.XPIProvider.addonChanged@XPIProvider.jsm:4369:18 <
> callProvider@AddonManager.jsm:236:12 <
> AddonManagerInternal.notifyAddonChanged@AddonManager.jsm:1807:7 <
> this.AddonManagerPrivate.notifyAddonChanged@AddonManager.jsm:3072:5 <
> _setCurrentTheme@LightweightThemeManager.jsm:709:3 < set
> currentTheme@LightweightThemeManager.jsm:148:12 <
> this.LightweightThemeManager.addBuiltInTheme@LightweightThemeManager.jsm:190:
> 7 < BG__finalUIStartup@nsBrowserGlue.js:707:7 <
> BG_observe@nsBrowserGlue.js:191:9
> ---
> (Build 52.0a1/20161030030204)
> 
> mozregression:
> 10:40.05 INFO: Last good revision: 14277a31e124303c85890f363b31f12dab245f72
> 10:40.05 INFO: First bad revision: 41a2caef2b66d3dca1debe1ac5b4fea58d0fe6f5
> 10:40.05 INFO: Pushlog:
> https://hg.mozilla.org/integration/mozilla-inbound/
> pushloghtml?fromchange=14277a31e124303c85890f363b31f12dab245f72&tochange=41a2
> caef2b66d3dca1debe1ac5b4fea58d0fe6f5
> 
> 10:40.92 INFO: Looks like the following bug has the changes which introduced
> the regression:
> https://bugzilla.mozilla.org/show_bug.cgi?id=1164954

What platform(s) do you see this on, and does this happen on every startup or just sometimes? I am not able to repro on OS X 10.11 so far.

From the code linked in comment 1 though this path is only taken if an async load is still in-progress, so I wonder if it only happens on machines with slow/busy disk.

I'll see if we're getting anything in Telemetry for XPIDB_overlapped_load too.
Flags: needinfo?(euthanasia_waltz)
AFAICT, this happens on Windows10 x64(1607), Linux Mint 18 x64(MATE), Manjaro Linux 16.10 x64(XFce), every startup.
(CPUs are Core i3-4010U(1.70GHz) and Celeron N2830(2.16GHz))

FWIW, there is a warning just before the error message, always, all platforms.
1477950798559	addons.xpi-utils	WARN	Synchronous load of XPI database due to getAddonsByType(theme)
Flags: needinfo?(euthanasia_waltz)
(In reply to Robert Helmer [:rhelmer] from comment #3)
> I'll see if we're getting anything in Telemetry for XPIDB_overlapped_load
> too.

I am a telemetry newb so pretty sure I am doing this wrong, looks like we are getting submissions with this probe:

https://telemetry.mozilla.org/new-pipeline/evo.html#!aggregates=median&cumulative=0&end_date=2016-10-19&keys=!__none__!__none__&max_channel_version=release%252F49&measure=SIMPLE_MEASURES_ADDONMANAGER_XPIDB_OVERLAPPED_LOAD&min_channel_version=release%252F46&product=Firefox&sanitize=1&sort_keys=submissions&start_date=2016-10-13&trim=1&use_submission_date=1
(In reply to atlanto from comment #4)
> AFAICT, this happens on Windows10 x64(1607), Linux Mint 18 x64(MATE),
> Manjaro Linux 16.10 x64(XFce), every startup.
> (CPUs are Core i3-4010U(1.70GHz) and Celeron N2830(2.16GHz))
> 
> FWIW, there is a warning just before the error message, always, all
> platforms.
> 1477950798559	addons.xpi-utils	WARN	Synchronous load of XPI database due to
> getAddonsByType(theme)

Thanks, I do see this on Mac now.
marking triaged and P3 - as rhelmer already took.  priority could be changed - but setting removes from untriaged list.
Priority: -- → P3
Whiteboard: triaged
I'm seeing this happen on all the platforms with the latest version of m-a (fx52.0a2). Used the following STR:

* install the latest m-a (used the build listed below)
* once installed, launch m-c and open the browser console, you shouldn't see the error on the initial launch
* close/restart m-a and you should see the error displayed under the browser console

You should see the same error in the browser console every time m-a is re-launched.

Platforms Used:
* macOS 10.12.1 x64 - reproduced several times
* Ubuntu 16.04.1 LTS VM - reproduced several times
* Win 10 x64 VM - reproduced several times

Browser Console error:
* https://pastebin.mozilla.org/8928582

Build being used:
* https://archive.mozilla.org/pub/firefox/nightly/2016/11/2016-11-15-00-40-18-mozilla-aurora/
(In reply to Kamil Jozwiak [:kjozwiak] from comment #8)
> I'm seeing this happen on all the platforms with the latest version of m-a
> (fx52.0a2). Used the following STR:

Thanks. I have a patch that at least handles the promise correctly, I think the fact that we're doing a synchronous DB load is a different issue but still important so I will file a followup for that.
Comment on attachment 8811027 [details]
Bug 1313960 - synchronous addon DB loader should handle in-progress async load

Actually hold off on reviewing this while I look into a test failure.
Attachment #8811027 - Flags: review?(kmaglione+bmo)
Comment on attachment 8811027 [details]
Bug 1313960 - synchronous addon DB loader should handle in-progress async load

https://reviewboard.mozilla.org/r/93274/#review93338
Attachment #8811027 - Flags: review?(kmaglione+bmo) → review+
try run: https://treeherder.mozilla.org/#/jobs?repo=try&revision=c69371916f6e1c61b6743a25174e7f37b882c141

I think this is the bare minimum change to make this work as originally intended and stop throwing an exception. Note that there was a bug in `asyncLoadDB` - it's checking `this._addonsDB` but that is never set, only `this.addonsDB`, but now async load should resolve early if a sync load has completed in the meantime.

It does not attempt to change the sync vs. async behavior. aswan, kmag and I have been discussing in IRC what we could do about this in the short term. In the longer term WebExtensions will probably replace themes so I'm not sure we should spend much time on this specifically right now, but I would like to better understand the current behavior so I'll probably look into that then file a followup bug if appropriate.

From manual testing and not breaking existing tests I believe that this is a safe change, however as far as I can tell we don't have any direct test for this behavior (to be fair to the original author, this sort of behavior can be hard to test, and it's easy to only think about the happy path...)
Pushed by rhelmer@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/ca88bad072d0
synchronous addon DB loader should handle in-progress async load r=kmag
https://hg.mozilla.org/mozilla-central/rev/ca88bad072d0
Status: ASSIGNED → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla53
Will ride the trains
You need to log in before you can comment on or make changes to this bug.