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.

Markh, given the recent work in error bars, can you verify if this problem still exists?

After bug 1180587 we will not see error bars, but we should still handle this situation better.

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.

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)`?

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

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

[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