Closed
Bug 1055616
Opened 10 years ago
Closed 9 years ago
Gracefully handle Sync of addons with missing or non-trusted sourceURI
Categories
(Firefox :: Sync, defect, P2)
Firefox
Sync
Tracking
()
RESOLVED
FIXED
Firefox 46
Tracking | Status | |
---|---|---|
firefox46 | --- | fixed |
People
(Reporter: gps, Assigned: markh)
Details
Attachments
(1 file)
(deleted),
patch
|
rnewman
:
review+
|
Details | Diff | Splinter Review |
Some IRC chatter revealed a likely Sync bug in the add-on engine.
Log A:
1408451474869 Sync.Engine.Addons DEBUG Refreshing reconciler state
1408451474869 Sync.AddonsReconciler INFO Refreshing global state from AddonManager.
1408451474871 Sync.AddonsReconciler DEBUG Rectifying state for addon: {195A3098-0BD5-4e90-AE22-BA1C540AFD1E}
1408451474871 Sync.AddonsReconciler DEBUG Rectifying state for addon: {02450914-cdd9-410f-b1da-db004e18c671}
1408451474871 Sync.AddonsReconciler DEBUG Rectifying state for addon: {972ce4c6-7e08-4474-a285-3208198ce6fd}
1408451474871 Sync.AddonsReconciler DEBUG Rectifying state for addon: firebug@software.joehewitt.com
1408451474871 Sync.AddonsReconciler DEBUG Rectifying state for addon: {07b90314-1e79-c84a-4b47-fb7e1853be39}
1408451474872 Sync.AddonsReconciler DEBUG Rectifying state for addon: {81bb8c83-39dc-8619-620a-20e24d2334dd}
1408451474873 Sync.AddonsReconciler DEBUG Rectifying state for addon: {1dd76e68-354a-331e-74af-fd3c9114fe0b}
1408451474873 Sync.AddonsReconciler DEBUG Rectifying state for addon: {26830ffd-2cdf-1085-2758-379d842c13f3}
1408451474873 Sync.AddonsReconciler DEBUG Rectifying state for addon: {37e0d66c-a12c-b343-6965-bd873213a0cd}
1408451474874 Sync.AddonsReconciler DEBUG Rectifying state for addon: {11b88c01-2bb2-4b2e-25cc-aefed565b0ee}
1408451474874 Sync.AddonsReconciler DEBUG Rectifying state for addon: {f0b3efbb-6ef1-0fed-35c7-f16b08b56f6b}
1408451474874 Sync.AddonsReconciler DEBUG Rectifying state for addon: {64be63fd-b52d-5c02-c372-1e415ed19b25}
1408451474874 Sync.AddonsReconciler DEBUG Rectifying state for addon: {e8b07081-2245-ee8f-0533-e17b1f475dfa}
1408451474874 Sync.AddonsReconciler DEBUG Rectifying state for addon: {f866c37a-90e8-8d22-6179-79a836a182c6}
1408451474875 Sync.AddonsReconciler INFO Saving reconciler state to file: addonsreconciler
1408451474892 Sync.Store.Addons DEBUG {37e0d66c-a12c-b343-6965-bd873213a0cd} not syncable: type not in whitelist: plugin
1408451474892 Sync.Engine.Addons INFO 0 outgoing items pre-reconciliation
1408451474893 Sync.BrowserIDManager DEBUG _ensureValidToken already has one
1408451474902 Sync.Engine.Addons ERROR null
1408451475734 Sync.AddonUtils INFO Found 1/1 add-ons during repository search.
1408451475735 Sync.AddonUtils INFO Skipping install of add-on because missing sourceURI: firefoxdav@icloud.com
1408451475735 Sync.Store.Addons WARN Failed to apply incoming record -j8Z_i7gQfGs
1408451475735 Sync.Store.Addons WARN Encountered exception: Error: Add-on not found after install: firefoxdav@icloud.com (resource://gre/modules/services-sync/engines/addons.js:309:6) JS Stack trace: create@addons.js:309:7 < Store.prototype.applyIncoming@engines.js:329:7 < applyIncoming@addons.js:279:5 < Store.prototype.applyIncomingBatch@engines.js:297:9 < doApplyBatch@engines.js:951:9 < SyncEngine.prototype._processIncoming/newitems.recordHandler@engines.js:1062:9 < Collection.prototype.recordHandler/this._onProgress@record.js:625:9 < Channel_onDataAvail@resource.js:542:7 < waitForSyncCallback@async.js:99:7 < Res__request@resource.js:389:7 < Res_get@resource.js:413:5 < SyncEngine.prototype._processIncoming@engines.js:1125:11 < SyncEngine.prototype._sync@engines.js:1481:7 < WrappedNotify@util.js:141:15 < Engine.prototype.sync@engines.js:655:5 < _syncEngine@enginesync.js:199:7 < sync@enginesync.js:149:13 < onNotify@service.js:1254:7 < WrappedNotify@util.js:141:15 < WrappedLock@util.js:96:9 < _lockedSync@service.js:1248:1 < sync/<@service.js:1239:7 < WrappedCatch@util.js:70:9 < sync@service.js:1227:5
1408451475736 Sync.Collection DEBUG mesg: GET success 200 https://sync-39-us-west-2.sync.services.mozilla.com/1.5/1838877/storage/addons?full=1&ids=-j8Z_i7gQfGs
1408451475736 Sync.Collection DEBUG GET success 200 https://sync-39-us-west-2.sync.services.mozilla.com/1.5/1838877/storage/addons?full=1&ids=-j8Z_i7gQfGs
1408451475736 Sync.Engine.Addons DEBUG Records that failed to apply: -j8Z_i7gQfGs
1408451475736 Sync.Engine.Addons INFO Records: 1 applied, 0 successfully, 1 failed to apply, 0 newly failed to apply, 0 reconciled.
1408451475737 Sync.Synchronizer INFO Sync completed at 2014-08-19 08:31:15 after 103.72 secs.
1408451475737 Sync.Declined DEBUG Handling remote declined: []
1408451475737 Sync.Declined DEBUG Handling local declined: []
1408451475737 Sync.Declined DEBUG Declined changed? false
1408451475737 Sync.Service INFO No change to declined engines. Not reuploading meta/global.
1408451475738 Sync.SyncScheduler DEBUG Next sync in 600000 ms.
1408451475738 Sync.ErrorHandler DEBUG Some engines did not sync correctly.
Log B:
1408452511416 Sync.Engine.Addons DEBUG Refreshing reconciler state
1408452511416 Sync.AddonsReconciler INFO Refreshing global state from AddonManager.
1408452511463 Sync.AddonsReconciler DEBUG Rectifying state for addon: {195A3098-0BD5-4e90-AE22-BA1C540AFD1E}
1408452511463 Sync.AddonsReconciler DEBUG Rectifying state for addon: web2pdfextension@web2pdf.adobedotcom
1408452511463 Sync.AddonsReconciler DEBUG Rectifying state for addon: {02450914-cdd9-410f-b1da-db004e18c671}
1408452511464 Sync.AddonsReconciler DEBUG Rectifying state for addon: {972ce4c6-7e08-4474-a285-3208198ce6fd}
1408452511464 Sync.AddonsReconciler DEBUG Rectifying state for addon: firebug@software.joehewitt.com
1408452511464 Sync.AddonsReconciler DEBUG Rectifying state for addon: {81bb8c83-39dc-8619-620a-20e24d2334dd}
1408452511464 Sync.AddonsReconciler DEBUG Rectifying state for addon: {07b90314-1e79-c84a-4b47-fb7e1853be39}
1408452511464 Sync.AddonsReconciler DEBUG Rectifying state for addon: {9c738794-70ae-13bb-ec20-a3ced687b60b}
1408452511464 Sync.AddonsReconciler DEBUG Rectifying state for addon: {f0b3efbb-6ef1-0fed-35c7-f16b08b56f6b}
1408452511464 Sync.AddonsReconciler DEBUG Rectifying state for addon: {59f388ba-f292-fa00-7cac-08235bd2d446}
1408452511464 Sync.AddonsReconciler DEBUG Rectifying state for addon: {1dd76e68-354a-331e-74af-fd3c9114fe0b}
1408452511465 Sync.AddonsReconciler DEBUG Rectifying state for addon: {26830ffd-2cdf-1085-2758-379d842c13f3}
1408452511465 Sync.AddonsReconciler DEBUG Rectifying state for addon: {37e0d66c-a12c-b343-6965-bd873213a0cd}
1408452511465 Sync.AddonsReconciler DEBUG Rectifying state for addon: {11b88c01-2bb2-4b2e-25cc-aefed565b0ee}
1408452511465 Sync.AddonsReconciler DEBUG Rectifying state for addon: {b0abad6a-59ad-ab23-b4cf-b9093349a0ed}
1408452511465 Sync.AddonsReconciler DEBUG Rectifying state for addon: {5775c363-5a70-79fc-e947-c7373be07b2d}
1408452511465 Sync.AddonsReconciler DEBUG Rectifying state for addon: {f7019fc2-77e1-dfdc-aa20-dce8aa9ebe02}
1408452511465 Sync.AddonsReconciler DEBUG Rectifying state for addon: {46202618-7f2d-bec9-10b1-3472a5e6b050}
1408452511466 Sync.AddonsReconciler INFO Saving reconciler state to file: addonsreconciler
1408452511474 Sync.Engine.Addons DEBUG First sync, uploading all items
1408452511475 Sync.Store.Addons DEBUG {972ce4c6-7e08-4474-a285-3208198ce6fd} not syncable: not installed in profile.
1408452511475 Sync.Store.Addons DEBUG {11b88c01-2bb2-4b2e-25cc-aefed565b0ee} not syncable: type not in whitelist: plugin
1408452511475 Sync.Store.Addons DEBUG {f0b3efbb-6ef1-0fed-35c7-f16b08b56f6b} not syncable: type not in whitelist: plugin
1408452511475 Sync.Store.Addons DEBUG {1dd76e68-354a-331e-74af-fd3c9114fe0b} not syncable: type not in whitelist: plugin
1408452511475 Sync.Store.Addons DEBUG {5775c363-5a70-79fc-e947-c7373be07b2d} not syncable: type not in whitelist: plugin
1408452511475 Sync.Store.Addons DEBUG {26830ffd-2cdf-1085-2758-379d842c13f3} not syncable: type not in whitelist: plugin
1408452511475 Sync.Store.Addons DEBUG firefox-hotfix@mozilla.org not syncable: is a hotfix.
1408452511476 Sync.Store.Addons DEBUG {37e0d66c-a12c-b343-6965-bd873213a0cd} not syncable: type not in whitelist: plugin
1408452511476 Sync.Store.Addons DEBUG {c2db5b63-b731-b04a-dbe2-d2b937aed7d7} not syncable: type not in whitelist: plugin
1408452511476 Sync.Store.Addons DEBUG {59f388ba-f292-fa00-7cac-08235bd2d446} not syncable: type not in whitelist: plugin
1408452511476 Sync.Store.Addons DEBUG {46202618-7f2d-bec9-10b1-3472a5e6b050} not syncable: type not in whitelist: plugin
1408452511476 Sync.Store.Addons DEBUG web2pdfextension@web2pdf.adobedotcom not syncable: not installed in profile.
1408452511476 Sync.Store.Addons DEBUG {f7019fc2-77e1-dfdc-aa20-dce8aa9ebe02} not syncable: type not in whitelist: plugin
1408452511476 Sync.Store.Addons DEBUG {81bb8c83-39dc-8619-620a-20e24d2334dd} not syncable: type not in whitelist: plugin
1408452511476 Sync.Store.Addons DEBUG {07b90314-1e79-c84a-4b47-fb7e1853be39} not syncable: type not in whitelist: plugin
1408452511476 Sync.Store.Addons DEBUG {9c738794-70ae-13bb-ec20-a3ced687b60b} not syncable: type not in whitelist: plugin
1408452511476 Sync.Store.Addons DEBUG {b0abad6a-59ad-ab23-b4cf-b9093349a0ed} not syncable: type not in whitelist: plugin
1408452511476 Sync.Engine.Addons INFO 3 outgoing items pre-reconciliation
1408452511477 Sync.BrowserIDManager DEBUG _ensureValidToken already has one
1408452512011 Sync.AddonUtils INFO Found 1/1 add-ons during repository search.
1408452512011 Sync.AddonUtils INFO Skipping install of add-on because missing sourceURI: firefoxdav@icloud.com
1408452512012 Sync.Store.Addons WARN Failed to apply incoming record -j8Z_i7gQfGs
1408452512012 Sync.Store.Addons WARN Encountered exception: Error: Add-on not found after install: firefoxdav@icloud.com (resource://gre/modules/services-sync/engines/addons.js:309:6) JS Stack trace: create@addons.js:309:7 < Store.prototype.applyIncoming@engines.js:329:7 < applyIncoming@addons.js:279:5 < Store.prototype.applyIncomingBatch@engines.js:297:9 < doApplyBatch@engines.js:951:9 < SyncEngine.prototype._processIncoming/newitems.recordHandler@engines.js:1062:9 < Collection.prototype.recordHandler/this._onProgress@record.js:625:9 < Channel_onDataAvail@resource.js:542:7 < waitForSyncCallback@async.js:99:7 < Res__request@resource.js:389:7 < Res_get@resource.js:413:5 < SyncEngine.prototype._processIncoming@engines.js:1069:11 < SyncEngine.prototype._sync@engines.js:1481:7 < WrappedNotify@util.js:141:15 < Engine.prototype.sync@engines.js:655:5 < _syncEngine@enginesync.js:199:7 < sync@enginesync.js:149:13 < onNotify@service.js:1254:7 < WrappedNotify@util.js:141:15 < WrappedLock@util.js:96:9 < _lockedSync@service.js:1248:1 < sync/<@service.js:1239:7 < WrappedCatch@util.js:70:9 < sync@service.js:1227:5
1408452512016 Sync.Collection DEBUG mesg: GET success 200 https://sync-39-us-west-2.sync.services.mozilla.com/1.5/1838877/storage/addons?full=1
1408452512016 Sync.Collection DEBUG GET success 200 https://sync-39-us-west-2.sync.services.mozilla.com/1.5/1838877/storage/addons?full=1
1408452512016 Sync.Engine.Addons DEBUG Records that failed to apply: -j8Z_i7gQfGs
1408452512016 Sync.Engine.Addons INFO Records: 1 applied, 0 successfully, 1 failed to apply, 1 newly failed to apply, 4 reconciled.
1408452512016 Sync.Status DEBUG Status for engine addons: error.engine.reason.apply_fail
1408452512016 Sync.Status DEBUG Status.service: success.status_ok => error.sync.failed_partial
1408452512016 Sync.ErrorHandler DEBUG addons failed to apply some records.
1408452512017 Sync.Synchronizer INFO Sync completed at 2014-08-19 08:48:32 after 28.75 secs.
1408452512018 Sync.Declined DEBUG Handling remote declined: []
1408452512018 Sync.Declined DEBUG Handling local declined: []
1408452512018 Sync.Declined DEBUG Declined changed? false
1408452512018 Sync.Service INFO No change to declined engines. Not reuploading meta/global.
1408452512019 Sync.SyncScheduler DEBUG Next sync in 90000 ms.
1408452512019 Sync.ErrorHandler DEBUG Some engines did not sync correctly.
Relevant log lines:
1408451474902 Sync.Engine.Addons ERROR null
1408451475734 Sync.AddonUtils INFO Found 1/1 add-ons during repository search.
1408451475735 Sync.AddonUtils INFO Skipping install of add-on because missing sourceURI: firefoxdav@icloud.com
1408451475735 Sync.Store.Addons WARN Failed to apply incoming record -j8Z_i7gQfGs
1408451475735 Sync.Store.Addons WARN Encountered exception: Error: Add-on not found after install: firefoxdav@icloud.com (resource://gre/modules/services-sync/engines/addons.js:309:6) JS Stack trace: create@addons.js:309:7 < Store.prototype.applyIncoming@engines.js:329:7 < applyIncoming@addons.js:279:5 < Store.prototype.applyIncomingBatch@engines.js:297:9 < doApplyBatch@engines.js:951:9 < SyncEngine.prototype._processIncoming/newitems.recordHandler@engines.js:1062:9 < Collection.prototype.recordHandler/this._onProgress@record.js:625:9 < Channel_onDataAvail@resource.js:542:7 < waitForSyncCallback@async.js:99:7 < Res__request@resource.js:389:7 < Res_get@resource.js:413:5 < SyncEngine.prototype._processIncoming@engines.js:1125:11 < SyncEngine.prototype._sync@engines.js:1481:7 < WrappedNotify@util.js:141:15 < Engine.prototype.sync@engines.js:655:5 < _syncEngine@enginesync.js:199:7 < sync@enginesync.js:149:13 < onNotify@service.js:1254:7 < WrappedNotify@util.js:141:15 < WrappedLock@util.js:96:9 < _lockedSync@service.js:1248:1 < sync/<@service.js:1239:7 < WrappedCatch@util.js:70:9 < sync@service.js:1227:5
We skip the add-on yet print a backtrace and mark the engine as failed. That's not good, especially if error bars are triggered.
Flags: firefox-backlog+
Comment 1•9 years ago
|
||
Markh, given the recent work in error bars, can you verify if this problem still exists?
Flags: needinfo?(markh)
Priority: -- → P2
Assignee | ||
Comment 2•9 years ago
|
||
After bug 1180587 we will not see error bars, but we should still handle this situation better.
Flags: needinfo?(markh)
Summary: Add-on sync results in error bar if add-on missing sourceURI → Gracefully handle Sync of addons with missing sourceURI
Assignee | ||
Comment 3•9 years ago
|
||
Richard,
As part of our telemetry analysis we found many failures in the addons engine. I suspect most of them are due to addons without a sourceURI or ones that are loaded from an insecure domain.
I think we should just "silently" ignore such addons - there's no good reason I can see to treat them as failures to be retried next time - the addon's sourceURI isn't going to be different next time we try.
This required changing where we check the sourceURI's scheme, but I think it still looks sane. All tests pass with this change.
Attachment #8703990 -
Flags: feedback?(rnewman)
Comment 4•9 years ago
|
||
Comment on attachment 8703990 [details] [diff] [review]
0001-Bug-1055616-Skip-addons-addons-without-a-sourceURI-o.patch
Review of attachment 8703990 [details] [diff] [review]:
-----------------------------------------------------------------
::: services/sync/modules/addonutils.js
@@ +375,5 @@
> + // insecure sources for security reasons. The Addon Manager ensures
> + // that cert validation etc is performed.
> + let requireSecureURI = !options || options.requireSecureURI === undefined ?
> + true :
> + options.requireSecureURI;
I had to read this twice! :P
@@ +394,3 @@
> * Update the user disabled flag for an add-on.
> *
> * The supplied callback will ba called when the operation is
s/ba/be
::: services/sync/modules/engines/addons.js
@@ +298,5 @@
> // engine and the record will try to be applied later.
> let results = cb.wait();
>
> + for (let id of results.skipped) {
> + if (id == record.addonID) {
Can we make results.skipped a Set?
Or use `results.skipped.includes(id)`?
Attachment #8703990 -
Flags: feedback?(rnewman) → review+
Assignee | ||
Comment 5•9 years ago
|
||
(In reply to Richard Newman [:rnewman] from comment #4)
> ::: services/sync/modules/engines/addons.js
> @@ +298,5 @@
> > // engine and the record will try to be applied later.
> > let results = cb.wait();
> >
> > + for (let id of results.skipped) {
> > + if (id == record.addonID) {
>
> Can we make results.skipped a Set?
>
> Or use `results.skipped.includes(id)`?
installAddons and its callers have quite a bit of complexity due to allowing multiple addons to be specified in a single call - but that is never taken advantage of - it is only ever called with exactly one addon. I was even considering just nuking that complexity and calling it installAddon().
Assignee | ||
Comment 6•9 years ago
|
||
(In reply to Richard Newman [:rnewman] from comment #4)
> > + let requireSecureURI = !options || options.requireSecureURI === undefined ?
> > + true :
> > + options.requireSecureURI;
>
> I had to read this twice! :P
heh :) It now reads:
let requireSecureURI = true;
if (options && options.requireSecureURI !== undefined) {
requireSecureURI = options.requireSecureURI;
}
> s/ba/be
Done.
> Can we make results.skipped a Set?
>
> Or use `results.skipped.includes(id)`?
Went with .includes.
Assignee: nobody → markh
Summary: Gracefully handle Sync of addons with missing sourceURI → Gracefully handle Sync of addons with missing or non-trusted sourceURI
Assignee | ||
Comment 7•9 years ago
|
||
Comment 8•9 years ago
|
||
bugherder |
Status: NEW → RESOLVED
Closed: 9 years ago
status-firefox46:
--- → fixed
Resolution: --- → FIXED
Target Milestone: --- → Firefox 46
Comment 9•9 years ago
|
||
[bugday-20160323]
Not for testday; developer specific testing.
Status: RESOLVED,FIXED --> UNVERIFIED
Component:
Name Firefox
Version 46.0b4
Build ID 20160322075646
Update Channel beta
User Agent Mozilla/5.0 (Windows NT 6.1; WOW64; rv:46.0) Gecko/20100101 Firefox/46.0
OS Windows 7 SP1 x86_64
You need to log in
before you can comment on or make changes to this bug.
Description
•