724661 - Add-on syncing fails

Status: RESOLVED INCOMPLETE

(Firefox :: Sync, defect)

Description

[Andreas Wagner [:TheOne] [use NI]]

Attachment: Log file with errors 1

As soon as I enable syncing of add-ons in the preferences, some of my add-ons get disabled, others get enabled. Not a big deal, I correct the state in the add-ons manager and press "Sync now".

However, syncing add-ons state seems to fail, see attachments.

When I disabled add-on syncing, the sync process works fine.

Comment 1

[Andreas Wagner [:TheOne] [use NI]]

Attachment: Log file with errors 2

Comment 2

[Gregory Szorc [:gps]]

Comment on attachment 594782 [details]
Log file with errors 1

This log is most troubling.

Near the top we have:

1328551490142	Sync.Tracker.Addons	DEBUG	changeListener invoked: 4 [e-mail]
1328551490142	Sync.AddonsReconciler	INFO	Saving reconciler state to file: addonsreconciler
1328551490153	Sync.Store.Addons	DEBUG	onDisabling: [e-mail]
1328551491475	Sync.Store.Addons	INFO	Found 1/1 add-ons during repository search.

Then, we have a bunch of:

  1328551514750	Sync.Service	DEBUG	Exception: Could not acquire lock. Label: "service.js: sync". No traceback available

After a number of those, add-on sync continues:

1328561299440	Sync.AddonsReconciler	DEBUG	Add-on change: onOperationCancelled to [e-mail]
1328561299440	Sync.AddonsReconciler	DEBUG	Rectifying state for addon: [e-mail]
1328561299440	Sync.AddonsReconciler	DEBUG	Adding change because enabled state changed: [e-mail]
1328561299440	Sync.AddonsReconciler	INFO	Change recorded for [e-mail]

Finally, we have Sync throwing an exception with a stack trace at the bottom.

What I find interesting is the elapsed time when all those syncs try to start but can't since one is in progress: ~2 hours.

What I suspect is happening is Sync is performing a call (likely to the Add-on Manager) and the callback on call completion never occurs. Technically, a sync is still running all this time, so new syncs won't start.

When you closed Firefox, this triggered the exception because the application was aborting.

So, I have 2 questions: what and how. I would like to know what async call is running away. And, I would like to know how I can reproduce this so I can add a test and fix it.

If you can reproduce, can you up the services.sync.log.logger.engine.addons pref to "Trace" and submit a new log?

Comment 3

[Gregory Szorc [:gps]]

This also worries me:

1328561510800	Sync.Store.Addons	DEBUG	{d40f5e7b-d2cf-4856-b441-cc613eeffbe3} not syncable: is foreign install.
1328561510800	Sync.Engine.Addons	INFO	2 outgoing items pre-reconciliation
1328561511188	Sync.Store.Addons	INFO	Updating userDisabled flag: {d40f5e7b-d2cf-4856-b441-cc613eeffbe3} -> true
1328561511203	Sync.AddonsReconciler	DEBUG	Add-on change: onDisabling to {d40f5e7b-d2cf-4856-b441-cc613eeffbe3}
1328561511203	Sync.AddonsReconciler	DEBUG	Rectifying state for addon: {d40f5e7b-d2cf-4856-b441-cc613eeffbe3}
1328561511203	Sync.AddonsReconciler	DEBUG	Adding change because enabled state changed: {d40f5e7b-d2cf-4856-b441-cc613eeffbe3}
1328561511203	Sync.AddonsReconciler	INFO	Change recorded for {d40f5e7b-d2cf-4856-b441-cc613eeffbe3}
1328561511203	Sync.Tracker.Addons	DEBUG	changeListener invoked: 4 {d40f5e7b-d2cf-4856-b441-cc613eeffbe3}
1328561511204	Sync.AddonsReconciler	INFO	Saving reconciler state to file: addonsreconciler
1328561511206	Sync.Store.Addons	DEBUG	onDisabling: {d40f5e7b-d2cf-4856-b441-cc613eeffbe3}

It seems like changes to add-ons that should be ignored by Sync aren't being ignored.

Comment 4

[Andreas Wagner [:TheOne] [use NI]]

Well, I could reproduce, that's why I kept add-on syncing disabled, besides trying  every few weeks...until now. it does not occur anymore, at least not on this machine (Mac). I will test with my Win7 tomorrow.

Comment 5

[Gregory Szorc [:gps]]

What's boggling me is how add-on sync just "pauses" after:

1328551491475	Sync.Store.Addons	INFO	Found 1/1 add-ons during repository search.

This log entry is dropped first thing in AddonRepository.getAddonsByIDs's searchSucceeded callback. In that callback, we should be invoking AddonsEngine.installAddonFromSearchResult once (because 1 search result). And, the first line of that function drops a log entry at info level. That log entry is never being recorded, implying that function is never being called. I'm looking at the code and can't figure out where things might be exploding inside the getAddonsByIDs callback. If we raise, that unfortunately wouldn't be caught by AddonRepository. So, I'm not sure how the error would propagate. It could even be swallowed by XPCOM. Ugh.

Comment 6

[Andreas Wagner [:TheOne] [use NI]]

So, here on my Win7 machine I don't get any errors but it seems also that the add-on status (enabled vs disabled) is not synced.

Example: On my Mac, I have the add-on compatibility reporter enabled, as I said in Comment 4, the last sync worked fine, but here on my Mac it does not get enabled when syncing (and no error is logged either).

Comment 7

[Andreas Wagner [:TheOne] [use NI]]

Attachment: Log with add-on sync level trace enabled

So, here is another log file from my Mac while add-on sync log level Trace was enabled.

I clicked on the "Sync Now" button a couple of times cause I notices the Sync icon does not animate when clicking on it, so I thought there is an error somewhere. I looked at the error console, but no output regarding sync stuff.

After waiting some minutes I restarted Firefox. I clicked on "Sync now" again, and it's "syncing" (at least the button is animated) for about ten minutes now. When it's finished, I'll upload it here, too.

Some of my add-ons again got disabled in the add-on manager.

Comment 8

[Andreas Wagner [:TheOne] [use NI]]

Ok, the current sync cycle just finished, but didn't produce a log file. I guess it failed again somehow. I can click on the "Sync button" as often as I want, and it does not animate even for a fraction of a second.

This time I got two errors in the error console:
Error: addon.sourceURI is null
Source file: resource://app/modules/services-sync/engines/addons.js
Line: 972
 ----------
Error: Aborting due to channel inactivity. = NS_ERROR_NET_TIMEOUT
Source file: resource://app/modules/services-sync/resource.js
Line: 628

Furthermore, when I hover over the toolbar button it says: "Last sync: Tue 06:51". Don't know whether this is local timezone or UTC, anyway, my local timezone is UTC+1.

HTH

Comment 9

[Gregory Szorc [:gps]]

I just recalled that the add-on compatibility reporter is now shipped with Firefox itself. If you used add-on sync when this extension was separate, Sync would still be trying to apply that record, even though the target is a built-in extension. This isn't a case I had considered and thus add-on sync only checks add-on syncability on outgoing records, not incoming. We may be throwing an error when trying to make changes to a built-in add-on that isn't modifiable.

Blair: Can you give some background on the compatibility reporter and any special behavior it has that may be relevant here?

Comment 10

[Gregory Szorc [:gps]]

Andreas: That error console output is *very* helpful. There are likely a few bugs in play here. There may even be a beta uplift or two...

Comment 11

[Andreas Wagner [:TheOne] [use NI]]

Attachment: another log file

Ok, here is another logfile with the add-on compatibility reporter uninstalled. I cannot see that it is now built-in into Firefox. There are no "Compatibility buttons" in the add-ons manager. Are you sure about that?

What I noticed:
- A few seconds after pressing the Sync now button, the add-on "Better Privacy" got disabled again.
The same error as above (resource://app/modules/services-sync/engines/addons.js#972) was shown in the error console
- After some time, the Sync button stopped animating, so I thought the Sync was finished. I looked into the sync-log directory, no entry. However after a restart of Firefox, there was this attached log file.

Do you want me to send in more log files or test something specifically?

Comment 12

[Gregory Szorc [:gps]]

Andreas: please set services.sync.log.appender.console to "Debug" or "Trace" and let me know what you see in the Error Console when Sync appears to hang. This should print the log messages in real time, as opposed to buffering them. I'm interested in seeing what corresponds to Sync supposedly stopping.

Comment 13

[Andreas Wagner [:TheOne] [use NI]]

Attachment: Error console log message on level trace

Here we go.

Comment 14

[Gregory Szorc [:gps]]

Comment on attachment 595154 [details]
Error console log message on level trace

Yeah, we're throwing an uncaught exception causing Sync to effectively stop. I have a patch in progress.

Comment 15

[Andreas Wagner [:TheOne] [use NI]]

(In reply to Gregory Szorc [:gps] from comment #14)
> I have a patch in progress.

Great, thank you!

Comment 16

[Gregory Szorc [:gps]]

Bug 725083 should resolve the issue sufficiently. However, you will still see a Sync error because the record without a sourceURI will fail to apply. This failure will be recorded, but shouldn't impact the overall sync process. You can verify this by running a sync manually. You should see a failure in the logs but you should not see a sync error bar.

I intend to file more follow-up bugs to deal with the remaining, lesser priority issues.

Comment 17

[Andreas Wagner [:TheOne] [use NI]]

Attachment: error console output from m-c rev 86418

I tested on the latest m-c build (rev 86418). It took a while but when I now hover over the Sync now button, it says last sync was just a couple of minutes ago.

See the attached logfile from that run.

Comment 18

[Blair McBride [:Unfocused] (UNAVAILABLE)]

(Sorry for the delay, I'm still catching up after a holiday.)

(In reply to Gregory Szorc [:gps] from comment #9)
> I just recalled that the add-on compatibility reporter is now shipped with
> Firefox itself.

No it isn't. But Test Pilot is (for Aurora, at least... probably Beta too). But that shouldn't affect anything anyway.

Anyway, seems you got this sort in my absence :)

Comment 19

[David Hedlund]

Firefox ESR installed the add-ons when I log in with another profile of the same installation of Firefox ESR.

Preferences -> Sync -> Add-ons (checked)

Other settings are synced.

Comment 20

[David Hedlund]

I'm using GNU/Linux.

The problem have been reported here too: https://www.reddit.com/r/firefox/comments/609mbh/firefox_syncing_bookmarks_but_not_passwords_and/

Comment 21

[David Hedlund]

My browser: Firefox ESR 52.2.1 for GNU/Linux (64-bit).

Comment 22

[Mark Hammond [:markh] [:mhammond]]

public, could you please follow the instructions at https://wiki.mozilla.org/CloudServices/Sync/File_a_desktop_bug and attach any and all logs to this bug?

Comment 23

[David Hedlund]

(In reply to Mark Hammond [:markh] from comment #22)
> public, could you please follow the instructions at
> https://wiki.mozilla.org/CloudServices/Sync/File_a_desktop_bug and attach
> any and all logs to this bug?

I'm happy to tell you that it worked after all, it was just a temporary issue.

Comment 24

[Mark Hammond [:markh] [:mhammond]]

(In reply to public from comment #23)
> I'm happy to tell you that it worked after all, it was just a temporary
> issue.

Awesome, thanks for getting back to us. I'm going to close this bug as the other reports and log files are very old, and we've made a number of improvements to addon syncing over the last couple of years. Any ongoing issues should be reported in new bugs.