Last Comment Bug 712542 - sync add-on Enabled/Disabled state incorrect
: sync add-on Enabled/Disabled state incorrect
Status: VERIFIED FIXED
[inbound][verified in services]
:
Product: Cloud Services
Classification: Client Software
Component: Firefox Sync: Backend (show other bugs)
: unspecified
: All All
: P1 major (vote)
: mozilla13
Assigned To: Gregory Szorc [:gps]
:
:
Mentors:
Depends on: 728466
Blocks: 712715
  Show dependency treegraph
 
Reported: 2011-12-20 21:10 PST by dindog
Modified: 2012-03-02 11:39 PST (History)
10 users (show)
See Also:
Crash Signature:
(edit)
QA Whiteboard:
Iteration: ---
Points: ---
verified
fixed
verified


Attachments
Sync-log of new create profile (216.00 KB, text/plain)
2011-12-20 21:10 PST, dindog
no flags Details
log with Trace addon (66.19 KB, application/octet-stream)
2011-12-20 23:23 PST, dindog
no flags Details
Apply add-on changes pre-install, v1 (16.13 KB, patch)
2012-02-16 19:48 PST, Gregory Szorc [:gps]
rnewman: review+
blair: review+
lukasblakk+bugs: approval‑mozilla‑aurora+
lukasblakk+bugs: approval‑mozilla‑beta+
Details | Diff | Splinter Review

Description dindog 2011-12-20 21:10:18 PST
STR:
1. Reset sync, and click "sync now" to upload the my original profile to server. With some add-ons are enabled, some disabled.(and some of them not download from AMO as well, like userchrome.js)
2. Create a new profile, set up sync as replace data with sync server.
3. After it's done, restart, those add-on enabled/disabled state is quite different from the original profile.

The attachment is the sync-log of the new created profile
Comment 1 dindog 2011-12-20 21:10:57 PST
Created attachment 583386 [details]
Sync-log of new create profile
Comment 2 Gregory Szorc [:gps] 2011-12-20 21:27:23 PST
The posted log shows that add-on sync is installing a number of add-ons and *is* updating the flag to disabled on a few of them.

Can you tell me which add-ons are in the wrong state?

Also, the end of the log concerns me:

1324443893703	Sync.Store.Addons	INFO	Setting add-on Sync GUID to remote: tpCGFrcKU06y
1324443893704	Sync.Status	DEBUG	Status.sync: success.sync => error.login.reason.network
1324443893704	Sync.Status	DEBUG	Status.service: error.sync.failed_partial => error.sync.failed
1324443893704	Sync.Status	DEBUG	Status for engine addons: error.engine.reason.unknown_fail
1324443893704	Sync.Status	DEBUG	Status.service: error.sync.failed => error.sync.failed_partial
1324443893704	Sync.ErrorHandler	DEBUG	addons failed: Aborting due to channel inactivity. JS Stack trace: Res_get()@resource.js:483 < SyncEngine__processIncoming()@engines.js:912 < SyncEngine__sync()@engines.js:1225 < WrappedNotify()@util.js:148 < Engine_sync()@engines.js:517 < WeaveSvc__syncEngine([object Object])@service.js:1496 < ()@service.js:1389 < WrappedNotify()@util.js:148 < WrappedLock()@util.js:103 < _lockedSync()@service.js:1289 < ()@service.js:1280 < WrappedCatch()@util.js:77 < sync()@service.js:1268
1324443893704	Sync.Service	INFO	Sync completed at 2011-12-21 13:04:53 after 885.11 secs.
1324443893704	Sync.SyncScheduler	DEBUG	Next sync in 90000 ms.
1324443893705	Sync.ErrorHandler	DEBUG	Some engines did not sync correctly.

That's a new error to me. I wonder if you are bumping up against some kind of inactivity timer due to the number/size of add-ons you are waiting to be installed.

Thanks for the report.
Comment 3 dindog 2011-12-20 21:35:02 PST
Personal Menu (4.3.2)
Image Viewer (0.1.1)
Scriptish (0.1.5)
Tab Utilities (1.2pre17)
userChromeJS (1.4)
Stylish (1.2.4)
Execute JS (0.2.4)
Mason (0.3.7.9)
Hide Caption Titlebar Plus (2.4.1)
PopVideo (0.6.1)
xThunder (1.1.2)
Easy DragToGo+ (1.1.6 beta3)
FireGestures (1.6.6)
Adblock Plus (2.0.2a.3362)

The above is enabled. Below are disabled in original but enabled in new profile.
DOM inspector
Element Hiding Helper for Adblock Plus
Firebug
Lastpass
ScrapBook Plus
XPCOMViewer
============================================
is that possible that non-AMO extension confuse sync? I have two non-AMO add-on: userchrome.js and Image Viewer
Comment 4 Gregory Szorc [:gps] 2011-12-20 22:07:06 PST
For the case of Firebug, we have in the logs:

1324443796904	Sync.Store.Addons	INFO	Found 1/1 add-ons during repository search.
1324443796904	Sync.Store.Addons	INFO	Trying to install add-on from search result: firebug@software.joehewitt.com
1324443796904	Sync.Store.Addons	DEBUG	Manually obtaining install for firebug@software.joehewitt.com
1324443796905	Sync.Store.Addons	INFO	Installing firebug@software.joehewitt.com
1324443813420	Sync.SyncScheduler	DEBUG	Global Score threshold hit, triggering sync.
1324443813442	Sync.Service	DEBUG	User-Agent: Firefox/11.0a1 FxSync/1.14.0.20111220031159.
1324443813442	Sync.Service	INFO	Starting sync at 2011-12-21 13:03:33
1324443813442	Sync.Service	DEBUG	Exception: Could not acquire lock. Label: "service.js: sync". No traceback available
1324443813442	Sync.Service	INFO	Cannot start sync: already syncing?
1324443840509	Sync.AddonsReconciler	DEBUG	Add-on change: onInstalling to firebug@software.joehewitt.com
1324443840509	Sync.AddonsReconciler	INFO	Saving reconciler state to file: addonsreconciler
1324443840515	Sync.AddonsReconciler	DEBUG	Add-on change: onInstallEnded to firebug@software.joehewitt.com
1324443840515	Sync.AddonsReconciler	DEBUG	Rectifying state for addon: firebug@software.joehewitt.com
1324443840515	Sync.AddonsReconciler	DEBUG	Adding change because add-on not present locally: firebug@software.joehewitt.com
1324443840515	Sync.AddonsReconciler	INFO	Change recorded for firebug@software.joehewitt.com
1324443840515	Sync.Tracker.Addons	DEBUG	changeListener invoked: 1 firebug@software.joehewitt.com
1324443840515	Sync.AddonsReconciler	INFO	Saving reconciler state to file: addonsreconciler
1324443840517	Sync.Store.Addons	INFO	Add-on installed: firebug@software.joehewitt.com
1324443840517	Sync.Store.Addons	INFO	Setting add-on Sync GUID to remote: ncSsLu33w2zt
1324443840518	Sync.Store.Addons	INFO	Updating userDisabled flag: firebug@software.joehewitt.com -> true

The last line says that the extension is being disabled. If that setting is being lost somehow, that would be very troubling, especially since we have automated tests for this scenario.

If it isn't too troubling, could you create a new profile, enable logOnSucess (https://philikon.wordpress.com/2011/06/13/how-to-file-a-good-sync-bug/), and set services.sync.log.logger.engine.addons to "Trace" in about:config, restart, set up sync, perform a sync, restart, perform another sync, then attach your sync logs? This will help identify if/where the add-on is being re-enabled.
Comment 5 dindog 2011-12-20 23:23:08 PST
Created attachment 583404 [details]
log with Trace addon

The network to sync server is not good here, has a few time error pop-up.
Any way, the issue persist. And I don't know why after enabled services.sync.log.logger.engine.addons to "Trace", no log file found in original profile. All log in the ZIP are new profile.

Here is the list all addons in original profile:
Extensions  
Adblock Plus  2.0.2a.3362  true  {d10d0bf8-f5b5-c8b4-a8b2-2b9879e08c5d}  
Easy DragToGo+  1.1.6 beta3  true  pig1717@gmail.com  	  
Execute JS  0.2.4  true  {7067a92c-1db4-4e5e-869c-25f841287f8b}  	  
FireGestures  1.6.6  true  firegestures@xuldev.org  	  
Hide Caption Titlebar Plus  2.4.1  true  hidecaptionplus-dp@dummy.addons.mozilla.org  	  
Image Viewer  0.1.1  true  imageviewer@yy  	  
Mason  0.3.7.9  true  {F632A5EA-F825-4AE7-94B5-233CFBA9F423}  	  
Personal Menu  4.3.2  true  CompactMenuCE@Merci.chao  	  
PopVideo  0.6.1  true  lmnPopVideo@lshai.com  	  
Scriptish  0.1.5  true  scriptish@erikvold.com  	  
Stylish  1.2.4  true  {46551EC9-40F0-4e47-8E18-8E5CF550CFB8}  	  
Tab Utilities  1.2pre17  true  tabutils@ithinc.cn  	  
userChromeJS  1.4  true  userChromeJS@mozdev.org  	  
xThunder  1.1.2  true  xthunder@lshai.com  
=====================================================================================	  
AutoPager  0.7.1.0  false  autopager@mozilla.org  	  
DOM Inspector  2.0.10  false  inspector@mozilla.org  	  
Element Hiding Helper for Adblock Plus  1.1.4  false  elemhidehelper@adblockplus.org  	  
Element Inspector  0.0.3  false  InspectElement@zbinlin  	  
Encoding And Decoding  1.8  false  ead@ziyunfei  	  
Firebug  1.9.0b4  false  firebug@software.joehewitt.com  	  
FireCaptor  0.1.1  false  firecaptor@zbinlin  	  
IDM CC  7.3.10  false  mozilla_cc@internetdownloadmanager.com  	  
keyconfig  20110522  false  keyconfig@dorando  	  
LastPass  1.80.0  false  support@lastpass.com  	  
ScrapBook Plus  1.8.20.34  false  scrapbookplus@addons.mozilla.org  	  
switch-to-tab Blacklist  1.1  false  switchToTabBlacklist@zpao.com  	  
XPCOMViewer  1.3.1  false  xpcomviewer@ondrejd.com  




and this is the new sync profile:
Adblock Plus    2.0.1    true    {d10d0bf8-f5b5-c8b4-a8b2-2b9879e08c5d}      
AutoPager    0.7.1.0    true    autopager@mozilla.org      
Easy DragToGo+    1.1.3.1    true    pig1717@gmail.com      
Execute JS    0.2.4    true    {7067a92c-1db4-4e5e-869c-25f841287f8b}      
Firebug    1.8.4    true    firebug@software.joehewitt.com      
FireGestures    1.6.6    true    firegestures@xuldev.org      
Hide Caption Titlebar Plus    2.4.1    true    hidecaptionplus-dp@dummy.addons.mozilla.org      
Mason    0.3.7.9    true    {F632A5EA-F825-4AE7-94B5-233CFBA9F423}      
Personal Menu    5.0.6    true    CompactMenuCE@Merci.chao      
PopVideo    0.6.1    true    lmnPopVideo@lshai.com      
Scriptish    0.1.5    true    scriptish@erikvold.com      
Stylish    1.2.4    true    {46551EC9-40F0-4e47-8E18-8E5CF550CFB8}      
Tab Utilities    1.1.2    true    tabutils@ithinc.cn      
xThunder    1.1.2    true    xthunder@lshai.com      
========================================================================
DOM Inspector    2.0.10    false    inspector@mozilla.org      
Element Hiding Helper for Adblock Plus    1.1.4    false    elemhidehelper@adblockplus.org      
Element Inspector    0.0.3    false    InspectElement@zbinlin      
FireCaptor    0.1.1    false    firecaptor@zbinlin      
IDM CC    7.3.10    false    mozilla_cc@internetdownloadmanager.com      
LastPass    1.80.0    false    support@lastpass.com      
ScrapBook Plus    1.8.20.34    false    scrapbookplus@addons.mozilla.org      
switch-to-tab Blacklist    1.1    false    switchToTabBlacklist@zpao.com      
XPCOMViewer    1.3.1    false    xpcomviewer@ondrejd.com        


It's better than yesterday, because lastpass don't support 12a1(can't enable).
But autopager, firebug still wrong
Comment 6 dindog 2011-12-20 23:25:50 PST
these addons in original profile below is not host on AMO:

Adblock Plus  2.0.2a.3362  true  {d10d0bf8-f5b5-c8b4-a8b2-2b9879e08c5d} 
Image Viewer  0.1.1  true  imageviewer@yy
userChromeJS  1.4  true  userChromeJS@mozdev.org  
keyconfig  20110522  false  keyconfig@dorando
Comment 7 Wes Kocher (:KWierso) 2012-01-01 21:08:22 PST
Hrm. In my laptop's main profile, I had a bunch (12+) of extensions get synced over and enabled, even though all but 4 were disabled on my desktop profile. 

But then I created a new profile on my laptop to try it again, and only the four enabled-and-AMO-hosted extensions from my desktop profile got synced over and enabled. Everything else did not sync at all.

Not sure what to think, now...
Comment 8 Gregory Szorc [:gps] 2012-01-02 10:40:04 PST
KWierso: I'd be interested in seeing the logs from the case where extensions didn't get synced over at all. If you don't see logs for the failure case, see https://philikon.wordpress.com/2011/06/13/how-to-file-a-good-sync-bug/ for how to crank up logging. If you could also crank up services.sync.log.logger.engine.addons to Trace, that would be helpful.
Comment 9 Gregory Szorc [:gps] 2012-02-16 16:27:34 PST
I'm able to reproduce this :(

STR:

1) Install a few non-restartless add-ons on profile A
2) Disable a few of them. Perform application restarts as requested.
3) Replace remote sync data with local data to ensure server data is authoritative (this isn't strictly necessary but ensures reproducibility)
4) Set up Sync on a fresh profile.
5) Witness add-on sync failing.

Here are the relevant logs:

1329436712060	Sync.Engine.Addons	TRACE	Incoming: { id: _YlqX-1TbMBa  index: 0  modified: 1329436619.8  ttl: undefined  payload: {"id":"_YlqX-1TbMBa","applicationID":"{ec8030f7-c20a-464f-9b0e-13a3a9e97384}","addonID":"{b9db16a4-6edc-47ec-a1f4-b86292ed211d}","enabled":false,"source":"amo"}  collection: addons }
1329436712060	Sync.Engine.Addons	TRACE	Reconciling _YlqX-1TbMBa. exists=false; modified=false; local age=null; incoming age=88.16000008583069
1329436712060	Sync.Engine.Addons	TRACE	No duplicate found for incoming item: _YlqX-1TbMBa
1329436712060	Sync.Engine.Addons	TRACE	Applying incoming because local item does not exist and was not deleted.
1329436712146	Sync.Store.Addons	INFO	Found 1/1 add-ons during repository search.
1329436712147	Sync.Store.Addons	INFO	Trying to install add-on from search result: {b9db16a4-6edc-47ec-a1f4-b86292ed211d}
1329436712147	Sync.Store.Addons	DEBUG	Obtaining install for {b9db16a4-6edc-47ec-a1f4-b86292ed211d}
1329436712148	Sync.Store.Addons	INFO	Installing {b9db16a4-6edc-47ec-a1f4-b86292ed211d}
1329436713999	Sync.AddonsReconciler	DEBUG	Add-on change: onInstalling to {b9db16a4-6edc-47ec-a1f4-b86292ed211d}
1329436713999	Sync.AddonsReconciler	INFO	Saving reconciler state to file: addonsreconciler
1329436714035	Sync.AddonsReconciler	DEBUG	Add-on change: onInstallEnded to {b9db16a4-6edc-47ec-a1f4-b86292ed211d}
1329436714035	Sync.AddonsReconciler	DEBUG	Rectifying state for addon: {b9db16a4-6edc-47ec-a1f4-b86292ed211d}
1329436714035	Sync.AddonsReconciler	DEBUG	Adding change because add-on not present locally: {b9db16a4-6edc-47ec-a1f4-b86292ed211d}
1329436714035	Sync.AddonsReconciler	INFO	Change recorded for {b9db16a4-6edc-47ec-a1f4-b86292ed211d}
1329436714036	Sync.Tracker.Addons	DEBUG	changeListener invoked: 1 {b9db16a4-6edc-47ec-a1f4-b86292ed211d}
1329436714036	Sync.AddonsReconciler	INFO	Saving reconciler state to file: addonsreconciler
1329436714127	Sync.Store.Addons	INFO	Add-on installed: {b9db16a4-6edc-47ec-a1f4-b86292ed211d}
1329436714127	Sync.Store.Addons	INFO	Setting add-on Sync GUID to remote: _YlqX-1TbMBa
1329436714127	Sync.Store.Addons	INFO	Updating userDisabled flag: {b9db16a4-6edc-47ec-a1f4-b86292ed211d} -> true

At this point, everything *looks* good from the logs. But, before I restart my browser, I see another sync performed. Relevant log entries:

1329436809228	Sync.Engine.Addons	TRACE	Event: weave:engine:sync:start
1329436809228	Sync.Engine.Addons	DEBUG	Refreshing reconciler state
1329436809228	Sync.AddonsReconciler	INFO	Refreshing global state from AddonManager.
1329436809330	Sync.Engine.Addons	DEBUG	Adding changed add-on from changes log: {b9db16a4-6edc-47ec-a1f4-b86292ed211d}
1329436809331	Sync.Engine.Addons	INFO	7 outgoing items pre-reconciliation
1329436809332	Sync.Engine.Addons	TRACE	Downloading & applying server changes
1329436809332	Sync.Engine.Addons	INFO	Records: 0 applied, 0 failed to apply, 0 newly failed to apply, 0 reconciled.
1329436809333	Sync.Engine.Addons	TRACE	Uploading local changes to server.
1329436809333	Sync.Engine.Addons	TRACE	Preparing 7 outgoing records
1329436809484	Sync.Engine.Addons	TRACE	Outgoing: { id: eMEeCC1DExAn  index: 0  modified: 1329436714.035  ttl: undefined  payload: {"id":"eMEeCC1DExAn","applicationID":"{ec8030f7-c20a-464f-9b0e-13a3a9e97384}","addonID":"{b9db16a4-6edc-47ec-a1f4-b86292ed211d}","enabled":true,"source":"amo"}  collection: addons }

This is chuck full of fail:

1) The outgoing record ID is set to eMEeCC1DExAn, not the original _YlqX-1TbMBa
2) The enabled flag is in the wrong boolean state

When the original profile performs its next sync, this bad state is propagated:

1329437308571	Sync.Engine.Addons	TRACE	Incoming: { id: eMEeCC1DExAn  index: 0  modified: 1329436809.71  ttl: undefined  payload: {"id":"eMEeCC1DExAn","applicationID":"{ec8030f7-c20a-464f-9b0e-13a3a9e97384}","addonID":"{b9db16a4-6edc-47ec-a1f4-b86292ed211d}","enabled":true,"source":"amo"}  collection: addons }
1329437308571	Sync.Engine.Addons	TRACE	Reconciling eMEeCC1DExAn. exists=false; modified=false; local age=null; incoming age=498.67000007629395
1329437308571	Sync.Engine.Addons	TRACE	Local item _YlqX-1TbMBa is a duplicate for incoming item eMEeCC1DExAn
1329437308571	Sync.Engine.Addons	DEBUG	Switching local ID to incoming: _YlqX-1TbMBa -> eMEeCC1DExAn
1329437308571	Sync.AddonsReconciler	INFO	Saving reconciler state to file: addonsreconciler
1329437308581	Sync.Engine.Addons	DEBUG	Local item after duplication: age=null; modified=false; exists=true
1329437308581	Sync.Engine.Addons	TRACE	Applying incoming record because no local conflicts.
1329437308643	Sync.Store.Addons	INFO	Updating userDisabled flag: {b9db16a4-6edc-47ec-a1f4-b86292ed211d} -> false
1329437308647	Sync.AddonsReconciler	DEBUG	Add-on change: onEnabling to {b9db16a4-6edc-47ec-a1f4-b86292ed211d}
1329437308647	Sync.AddonsReconciler	DEBUG	Rectifying state for addon: {b9db16a4-6edc-47ec-a1f4-b86292ed211d}
1329437308648	Sync.AddonsReconciler	DEBUG	Adding change because enabled state changed: {b9db16a4-6edc-47ec-a1f4-b86292ed211d}
1329437308648	Sync.AddonsReconciler	INFO	Change recorded for {b9db16a4-6edc-47ec-a1f4-b86292ed211d}
1329437308648	Sync.Tracker.Addons	DEBUG	changeListener invoked: 3 {b9db16a4-6edc-47ec-a1f4-b86292ed211d}
1329437308648	Sync.AddonsReconciler	INFO	Saving reconciler state to file: addonsreconciler
1329437308707	Sync.Store.Addons	DEBUG	onEnabling: {b9db16a4-6edc-47ec-a1f4-b86292ed211d}
1329437309249	Sync.Collection	DEBUG	mesg: DELETE success 200 https://scl2-sync1058.services.mozilla.com/1.1/7tdc3tv3fisrwyljfsrlzlxins7f4s54/storage/addons?ids=W5B9Ayp1MLsy,YLV5l76xL49d,5id7k7sIbiuL,eXDnj2sxy9od,_YlqX-1TbMBa,d8m3lf1c0Ow8,cHGXlYrWeKVM
1329437309249	Sync.Collection	DEBUG	DELETE success 200 https://scl2-sync1058.services.mozilla.com/1.1/7tdc3tv3fisrwyljfsrlzlxins7f4s54/storage/addons?ids=W5B9Ayp1MLsy,YLV5l76xL49d,5id7k7sIbiuL,eXDnj2sxy9od,_YlqX-1TbMBa,d8m3lf1c0Ow8,cHGX…

Then, on the next sync for the same profile:

1329437399355	Sync.Engine.Addons	TRACE	Event: weave:engine:sync:start
1329437399355	Sync.Engine.Addons	DEBUG	Refreshing reconciler state
1329437399355	Sync.AddonsReconciler	INFO	Refreshing global state from AddonManager.
1329437399367	Sync.AddonsReconciler	DEBUG	Rectifying state for addon: {b9db16a4-6edc-47ec-a1f4-b86292ed211d}
1329437399369	Sync.AddonsReconciler	INFO	Saving reconciler state to file: addonsreconciler
1329437399408	Sync.Engine.Addons	DEBUG	Adding changed add-on from changes log: {b9db16a4-6edc-47ec-a1f4-b86292ed211d}
1329437399475	Sync.Engine.Addons	TRACE	Preparing 2 outgoing records
1329437399475	Sync.Engine.Addons	TRACE	Outgoing: { id: eMEeCC1DExAn  index: 0  modified: 1329437308.648  ttl: undefined  payload: {"id":"eMEeCC1DExAn","applicationID":"{ec8030f7-c20a-464f-9b0e-13a3a9e97384}","addonID":"{b9db16a4-6edc-47ec-a1f4-b86292ed211d}","enabled":true,"source":"amo"}  collection: addons }

Ugh.
Comment 10 Gregory Szorc [:gps] 2012-02-16 19:48:00 PST
Created attachment 598111 [details] [diff] [review]
Apply add-on changes pre-install, v1

This patch seems to fix the issue of addon.{syncGUID, userDisabled} getting lost during install of non-restartless add-ons.

The change is to manipulate the AddonInstall's copy of the Addon object right before install. Previously, we did this manipulation after install, which apparently didn't work. I thought there was test coverage for this. I was wrong. This patch includes new test coverage. And, yes, the test failed before the engine was patched.

I'm not concerned about the API breaking change because nobody outside of Sync should be using it.

I'm requesting Unfocused's review for Add-on Manager API usage sanity. rnewman is traveling in the next few hours, so I'm adding mconnor as a back-up. Whoever gets to it first, "wins."

I've verified that Sync's xpcshell tests all pass with this patch. In addition, I've verified all of the add-on related TPS tests pass.

Because add-on sync is broken in all the trees, I will eventually request Aurora and Beta uplift for this fix. Therefore, I'd like a review ASAP to maximize the time for testing in the wild before Firefox 11 is released to the wild.
Comment 11 Blair McBride [:Unfocused] (UNAVAILABLE) 2012-02-16 20:38:05 PST
Comment on attachment 598111 [details] [diff] [review]
Apply add-on changes pre-install, v1

Review of attachment 598111 [details] [diff] [review]:
-----------------------------------------------------------------

Filed bug 728121 for the underlying cause of this. ie, to make it so you can set those properties whenever you want. Not a simple fix though, so this patch is the right approach.

::: services/sync/modules/engines/addons.js
@@ +743,5 @@
> +                       install.name);
> +              install.addon.userDisabled = true;
> +            }
> +
> +            return true;

Don't need to return anything here - it only matters if you explicitly return false.
Comment 12 Gregory Szorc [:gps] 2012-02-17 10:59:43 PST
When testing this today, both times I have created a new profile, I run into bug 702506 and get a bunch of about:newaddon on startup. Of course, Sync is loaded when these tabs are open. And, on first sync, Sync looks at the state of the world and sees that no add-ons are installed. This causes Sync to upload deleted records, which will propagate as uninstalls to other devices. NOT COOL.

I was experiencing this behavior yesterday when reproducing this bug, so it occurred before the patch was applied. I /think/ this patch is safe to apply because it fixes broken behavior in add-on sync. However, I'm not sure if it increases the probability of bug 702506.

We may need to reconsider having add-on sync enabled in light of bug 702506.
Comment 13 Gregory Szorc [:gps] 2012-02-17 11:02:51 PST
It gets worse. When I go to an about:newaddon tab and click through to allow it to be installed, when I restart (as I'm prompted to) before I've clicked through all the tabs, some add-ons are lost on restart. By "lost" I mean that they don't appear in about:addons and there is no about:newaddon tab for them. Before the restart, I could see the add-ons listed as disabled in about:addons and they had an about:newaddon tab.
Comment 14 Gregory Szorc [:gps] 2012-02-17 11:08:01 PST
So, the lost add-ons appear to be getting uninstalled by Sync.

On the initial app load when all the about:newaddons tabs are opened, Sync uploads deleted records for all the add-ons. When I restart after clicking through about:newaddon or I wait until Sync runs again, Sync will see these deleted records and will uninstall the add-on locally because for whatever reason, Sync is able to see some of these add-ons in the Add-on Manager APIs on the 2nd application restart.

Wut?
Comment 15 Gregory Szorc [:gps] 2012-02-17 11:21:18 PST
And I just got it to work on a fresh profile. No about:newaddon on post-initial-sync restart. So, I don't think this patch regresses anything.
Comment 16 Gregory Szorc [:gps] 2012-02-17 11:21:40 PST
And I just got it to work on a fresh profile. No about:newaddon on post-initial-sync restart. So, I don't think this patch regresses anything.
Comment 17 Gregory Szorc [:gps] 2012-02-17 16:12:14 PST
It's looking like the database corruption issues were caused by Add-on Compatibility Reporter and Sync just happens to trigger this existing bug.

I think we should move forward with this patch (it doesn't make anything worse and makes Sync work properly in the case where ACR isn't installed). Then, we can evaluate the ACR bug separately next week.
Comment 18 Richard Newman [:rnewman] 2012-02-20 12:07:56 PST
Comment on attachment 598111 [details] [diff] [review]
Apply add-on changes pre-install, v1

Review of attachment 598111 [details] [diff] [review]:
-----------------------------------------------------------------

Looks good to me, given my limited knowledge of the API you're using :D

::: services/sync/modules/engines/addons.js
@@ +318,5 @@
>     */
>    create: function create(record) {
>      // Ideally, we'd set syncGUID and userDisabled on install. For now, we
>      // make the changes post-installation.
>      // TODO Set syncGUID and userDisabled in one step, during install.

Is this comment still accurate?

@@ +1051,5 @@
>          // as they finish, eventually triggering the global callback.
>          for each (let addon in toInstall) {
> +          let options = {};
> +          for each (let install in installs) {
> +            if (install.id == addon.id) {

John McCarthy cried, each of his tears an alist. He weeps behind the bars of a cons cell.

::: services/sync/tests/unit/test_addons_engine.js
@@ +151,5 @@
> +
> +  const USER = "foo";
> +  const PASSWORD = "password";
> +  const PASSPHRASE = "abcdeabcdeabcdeabcdeabcdea";
> +  const ADDON_ID = "addon1@tests.mozilla.org";

Nit: align =.

@@ -140,2 +241,2 @@
> >    Log4Moz.repository.getLogger("Sync.AddonsRepository").level =
> >      Log4Moz.Level.Trace;

Long lines be damned.
Comment 20 Gregory Szorc [:gps] 2012-02-20 14:58:29 PST
Comment on attachment 598111 [details] [diff] [review]
Apply add-on changes pre-install, v1

[Approval Request Comment]
Regression caused by (bug #): 534956 (initial add-on sync drop)
User impact if declined: Add-on enabled state may not sync properly.
Testing completed (on m-c, etc.): None yet. Should probably bake a few days. Will have explicit QA verification.
Risk to taking this patch (and alternatives if risky): Low. This patch fixes broken behavior in add-on sync.
String changes made by this patch: None

To whoever looks at this request, there are some scary-looking comments in this bug. We're confident that this patch isn't related and have since fingered the add-on compatibility reporter as the culprit.

If this patch doesn't get in beta, we would likely need to pref off add-on sync in beta because it would be fundamentally broken.
Comment 21 Ed Morley [:emorley] 2012-02-21 08:48:50 PST
https://hg.mozilla.org/mozilla-central/rev/dec32ab636c6
Comment 22 Alex Keybl [:akeybl] 2012-02-21 11:36:34 PST
(In reply to Gregory Szorc [:gps] from comment #20)
> Comment on attachment 598111 [details] [diff] [review]
> Apply add-on changes pre-install, v1
> 
> [Approval Request Comment]
> Regression caused by (bug #): 534956 (initial add-on sync drop)
> User impact if declined: Add-on enabled state may not sync properly.
> Testing completed (on m-c, etc.): None yet. Should probably bake a few days.
> Will have explicit QA verification.

Because this needs a few days to bake, we'll be taking this for Beta 5 if approved. That's pretty late in the game, but since the feature can be pref'd of remotely if necessary, we may decide to move ahead with add-on sync in FF11. In the meantime, we'll hold this bug in the queue.

> Risk to taking this patch (and alternatives if risky): Low. This patch fixes
> broken behavior in add-on sync.
> String changes made by this patch: None
> 
> To whoever looks at this request, there are some scary-looking comments in
> this bug. We're confident that this patch isn't related and have since
> fingered the add-on compatibility reporter as the culprit.

We'll track bug 728466 for this investigation (please correct me if that's wrong).
Comment 23 Tracy Walker [:tracy] 2012-02-21 14:51:03 PST
verified with s-c train builds of 20120221 following steps in comment 9

Note You need to log in before you can comment on or make changes to this bug.