atlanto Reporter
	Description • 8 years ago

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

	:Gijs (he/him)
	Comment 1 • 8 years ago

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?

	Dave Townsend [:mossop]
	Comment 2 • 8 years ago

(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.

	Robert Helmer [:rhelmer] Assignee
	Comment 3 • 8 years ago

(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.

	atlanto Reporter
	Comment 4 • 8 years ago

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)

	Robert Helmer [:rhelmer] Assignee
	Comment 5 • 8 years ago

(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

	Robert Helmer [:rhelmer] Assignee
	Comment 6 • 8 years ago

(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.

	:shell escalante
	Comment 7 • 8 years ago

marking triaged and P3 - as rhelmer already took.  priority could be changed - but setting removes from untriaged list.

	Kamil Jozwiak [:kjozwiak]
	Comment 8 • 8 years ago

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/

	Robert Helmer [:rhelmer] Assignee
	Comment 9 • 8 years ago

(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.

	Robert Helmer [:rhelmer] Assignee
	Comment 11 • 8 years ago

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.

	Kris Maglione [:kmag]
	Comment 13 • 8 years ago
mozreview-review

Comment on attachment 8811027 [details]
Bug 1313960 - synchronous addon DB loader should handle in-progress async load

https://reviewboard.mozilla.org/r/93274/#review93338

	Robert Helmer [:rhelmer] Assignee
	Comment 14 • 8 years ago

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...)

	Pulsebot
	Comment 15 • 8 years ago

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

	Carsten Book [:Tomcat]
	Comment 16 • 8 years ago
bugherder

https://hg.mozilla.org/mozilla-central/rev/ca88bad072d0

	Sylvestre Ledru [:Sylvestre]
	Comment 17 • 7 years ago

Will ride the trains