1286618 - Sync doesn't start immediately if something schedules a regular sync before autoConnect is called.

Status: NEW

(Firefox :: Sync, defect, P3)

Description

[jeremy9856]

User Agent: Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:47.0) Gecko/20100101 Firefox/47.0
Build ID: 20160623084759

Steps to reproduce:

I have 2 computers and I often need to manually start the sync just after launching Firefox because it doesn't start right after Firefox is launched. I don't know why but it seem that there is a delay. I don't know how much delay since I manually start the sync to sync the bookmarks I need to start working.

The Sync should start as soon as possible at the launch of Firefox. Thanks !

Comment 1

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

Sync does already start very soon after startup - the exact time taken depends on the number of tabs being restored - we want to delay the first sync until the browser had loaded and is ready to be interacted with as we don't feel Sync should make the browser unusable while it is running. For a new session, a Sync will typically start withing 5 seconds or so after the browser has initialized and the longest it will take is 300 seconds (if many tabs are being restored), but if the previous Sync before shutdown was less than 10 minutes ago, we wait for that 10 minutes (as that is when we would have Synced if no shutdown in the meantime)

I'm going to close this as WONTFIX as this behaviour is by design, but please let us know if you are finding Sync taking a significantly longer time to start Syncing than described above.

Comment 2

[jeremy9856]

I only sync bookmarks and passwords. I'm a new user of Firefox and indeed sometimes the sync is fast but sometimes it can take a while. I will make more tests. Is there a command that I should run to gather some data if it happen again ?

Comment 3

[jeremy9856]

It don't seem to happen on my desktop but it clearly happen on my laptop. I just waked up my laptop, started Firefox, and it took 10mn for the sync to start !

Comment 4

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

Could you please attach a Sync log when you experience this problem? See https://wiki.mozilla.org/CloudServices/Sync/File_a_desktop_bug for details and note that you will probably need to set the logOnSuccess pref mentioned in that page (and you may like to submit a few such logs from around the problem time as the information might be in one of a few logs)

Comment 5

[jeremy9856]

Attachment: sync-log.txt

I enabled logOnSuccess and here is a Sync log where the sync took 10mn to start whereas there was new bookmarks to sync.

Comment 6

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

This is odd. The log line:

> 1469196438096	Sync.SyncScheduler	DEBUG	Clearing sync triggers and the global score.

implies that at this point we've cleared the "next sync" time - but then the log clearly shows it will wait for 10 minutes. Sadly I can't reproduce this. Would it be possible for you to set the pref "services.sync.log.logger.service.main" to the string "Trace", reproduce the issue again and attach that log? I'm hoping that will give some more insights into what is going on. Thanks!

Comment 7

[jeremy9856]

It don't happen for now. As soon as it do it again I will post the log.
Thank you!

Comment 8

[jeremy9856]

Attachment: success-sync-1469712339065.txt

It happened again. I launched Firefox at 3:15PM and nothing happened, no sync. I waited until the sync started and that happen at 3:25PM. Again a 10mn delay whereas there was some bookmarks to sync.

Comment 9

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

Thanks - this makes things clearer - although it's actually quite a mess.

* Sync stores "nextSync" in preferences - the idea is (presumably) that if a Sync happened (say) 5 minutes ago and you restart the browser, the next Sync should be in 5 minutes. This sounds reasonable, however:

* As soon as Sync starts, it actually resets this "nextSync" value to zero - so the value isn't actually persisted. https://dxr.mozilla.org/mozilla-central/source/services/sync/modules/policies.js#63

* A little later, the browser tells Sync it has initialized so Sync can do its thing without impacting startup performance. However, this mechanism basically assumes "nextSync" is set sanely - it tells Sync to start in |nextSync - now()| ms. However, nextSync is typically 0, so this always ends up being calculated as "a long time ago" - which means Sync starts immediately. https://dxr.mozilla.org/mozilla-central/source/services/sync/modules/policies.js#482

Where this is going wrong is that in this case, between Sync initializing and the browser telling Sync it is ready, a new Sync has *already* been scheduled for 10 minutes, and "nextSync" has been set appropriately to 10 minutes into the future. Thus, when Sync is told to start in |nextSync - now()|, that is still 10 minutes away.

The reason this is happening in your case is that the greasemonkey engine is telling Sync that something has changed as Sync initializes. I can reproduce this with the path below to the bookmarks engine - with that patch applied, Sync waits 10 minutes after startup. greasemonkey really shouldn't be doing this, but we should also deal with it correctly.

Richard, do you have insights here? ISTM the nextSync mechanism is broken here (ie, that in the typical case, Sync always runs at startup regardless of when the last sync actually was). The scheduler code is quite a mess, and it seems the easiest thing to do it to have that autoConnect code always schedule a sync for "now", dropping the pretense that nextSync survives between runs - that sounds much easier than trying to fix the code to match the apparent intent. WDYT?

This patch will reproduce the problem:

--- a/services/sync/modules/engines/bookmarks.js
+++ b/services/sync/modules/engines/bookmarks.js
@@ -128,6 +128,9 @@ Utils.deferGetSet(BookmarkSeparator, "cleartext", "pos");

 this.BookmarksEngine = function BookmarksEngine(service) {
   SyncEngine.call(this, "Bookmarks", service);
+  Svc.Obs.add("weave:service:ready", function() {
+    this._tracker.score = 1;
+  }, this);
 }

Comment 10

[Anthony Lieuallen]

> The reason this is happening in your case is that the greasemonkey engine
> is telling Sync that something has changed as Sync initializes.

I (Greasemonkey maintainer) cannot confirm.  This must be related to some particular setting in your profile?  There's only one place that we (intentionally) set any sync related score:

https://github.com/greasemonkey/greasemonkey/blob/87d4e9a912aa46b32c68d866811b8bcd50a4f950/modules/sync.js#L222

And I don't see that being called at launch ( Mozilla/5.0 (X11; Linux x86_64; rv:51.0) Gecko/20100101 Firefox/51.0 ) when I insert log statements, though I do see it being called at the right application specific time (e.g. enable/disable a script).

Can you provide a bit more detail?

Comment 11

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

(In reply to Anthony Lieuallen from comment #10)
> https://github.com/greasemonkey/greasemonkey/blob/
> 87d4e9a912aa46b32c68d866811b8bcd50a4f950/modules/sync.js#L222
> 
> And I don't see that being called at launch ( Mozilla/5.0 (X11; Linux
> x86_64; rv:51.0) Gecko/20100101 Firefox/51.0 ) when I insert log statements,

To be clear, the log makes it appear as though it is happening immediately after the greasemonkey sync engine is instantiated:

1469711731750	Sync.Engine.Greasemonkey	DEBUG	Engine initialized
1469711731829	FirefoxAccounts	DEBUG	notifying profile changed for user 1bbece6e632e4a36b3d680897293011a
1469711731832	FirefoxAccounts	TRACE	not checking freshness of profile as it remains recent
1469711733361	Sync.SyncScheduler	TRACE	Handling weave:engine:score:updated
1469711733464	Sync.SyncScheduler	TRACE	clients: score: 0
1469711733465	Sync.SyncScheduler	TRACE	greasemonkey: score: 1
1469711733466	Sync.SyncScheduler	TRACE	passwords: score: 0
1469711733466	Sync.SyncScheduler	TRACE	bookmarks: score: 0
1469711733466	Sync.SyncScheduler	TRACE	Global score updated: 1


> though I do see it being called at the right application specific time (e.g.
> enable/disable a script).

The score value is 1, so I assume that must be the branch:

> } else if (aEvent in {'cludes': 1, 'val-set': 1, 'val-del': 1}) {

> Can you provide a bit more detail?

I'm afraid I don't have stack traces or anything further, but that log seems fairly clear re the score bump.

Thanks!

Comment 12

[Anthony Lieuallen]

I set `services.sync.log.appender.file.logOnSuccess` to true and relaunched my browser and I got a file:


$ egrep -i 'greasemonkey|score' success-sync-1470179353654.txt 
1470179345276   Sync.SyncScheduler      DEBUG   Clearing sync triggers and the global score.
1470179346284   Sync.Engine.Greasemonkey        DEBUG   Engine initialized
1470179353006   Sync.Service    INFO    Testing info/collections: {"passwords":1469823557.59,"tabs":1470169176.82,"clients":1470165575.53,"crypto":1469823435.96,"forms":1470164274.99,"meta":1469823559.84,"bookmarks":1469823558.6,"prefs":1469823557.26,"greasemonkey":1470169176.68,"history":1470169177.05}
1470179353024   Sync.SyncScheduler      DEBUG   Clearing sync triggers and the global score.
1470179353044   Sync.Service    INFO    Testing info/collections: {"passwords":1469823557.59,"tabs":1470169176.82,"clients":1470165575.53,"crypto":1469823435.96,"forms":1470164274.99,"meta":1469823559.84,"bookmarks":1469823558.6,"prefs":1469823557.26,"greasemonkey":1470169176.68,"history":1470169177.05}
1470179353224   Sync.Telemetry  TRACE   observed weave:engine:sync:start greasemonkey
1470179353224   Sync.Telemetry  INFO    Notification for engine greasemonkey, but we aren't recording telemetry for it
1470179353225   Sync.Engine.Greasemonkey        INFO    0 outgoing items pre-reconciliation
1470179353226   Sync.Engine.Greasemonkey        INFO    Records: 0 applied, 0 successfully, 0 failed to apply, 0 newly failed to apply, 0 reconciled.
1470179353226   Sync.Telemetry  TRACE   observed weave:engine:sync:applied greasemonkey
1470179353226   Sync.Telemetry  INFO    Notification for engine greasemonkey, but we aren't recording telemetry for it
1470179353226   Sync.Telemetry  TRACE   observed weave:engine:sync:finish greasemonkey


Which has the same engine initialized line but doesn't mention any score going up.  Does this happen for you in a clean profile?

Comment 13

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

(In reply to Anthony Lieuallen from comment #12)
> I set `services.sync.log.appender.file.logOnSuccess` to true and relaunched
> my browser and I got a file:

Note that you'll need to set the pref "services.sync.log.logger.service.main" to the string "Trace" to see the same detail as the referenced log.

However, I suspect that even then you will not see the issue - it looks as though a Sync started ~7 seconds after initialization - a symptom of this bug is that the first sync happens 10 minutes after startup.

> Does this happen for you in a clean profile?

FWIW, I can't reproduce it with the current GreaseMonkey and a single userscript installed. Is it possible a script might influence this as it loads?

(Note that as I mentioned above, this is somewhat of a tangent - I believe Sync should do the right thing even if we could demonstrate GreaseMonkey did this unconditionally. Happy to help get to the bottom of the GreaseMonkey side if I can though)

Comment 14

[jeremy9856]

I don't know if that can help but here is what I use :

Add-on
============
- Decentraleyes
- Greasemonkey
- Https everywhere
- Privacy badger
- uBlock origin
- Open with
- Stay open menu
- Tab wheel scroll

Greasemonkey Script
============
- anti-adblock-killer
 https://github.com/reek/anti-adblock-killer

user.js
============
// PERFORMANCE
user_pref("layers.acceleration.force-enabled", true);
user_pref("layers.offmainthreadcomposition.enabled", true);
user_pref("layers.offmainthreadcomposition.async-animations", true);
user_pref("layers.async-video.enabled", true);
user_pref("layout.frame_rate.precise", true);
user_pref("webgl.force-enabled", true);
user_pref("webgl.msaa-force", true);
user_pref("html5.offmainthread", true);
// PRIVACY
user_pref("loop.enabled", false);
user_pref("browser.pocket.enabled", false);
user_pref("privacy.trackingprotection.enabled", true);
user_pref("geo.enabled", false);
user_pref("browser.safebrowsing.enabled", false);
user_pref("browser.safebrowsing.malware.enabled", false);
user_pref("dom.event.clipboardevents.enabled", false);
user_pref("browser.send_pings", false);
user_pref("dom.battery.enabled", false);
// USABILITY
user_pref("browser.tabs.loadBookmarksInBackground", true);

Comment 15

[Anthony Lieuallen]

> Is it possible a script might influence this as it loads?

Yes.  I'm pretty sure I know what's happening.  I'll fix Greasemonkey separately ( https://github.com/greasemonkey/greasemonkey/issues/2414 ).

Comment 16

[jeremy9856]

Great ! Thank you very much Mark and Anthony !

Comment 17

[Richard Newman [:rnewman]]

(In reply to Mark Hammond [:markh] from comment #9)

> greasemonkey really shouldn't be doing
> this, but we should also deal with it correctly.

I don't really feel like this is something GreaseMonkey shouldn't be doing! That is, it should be totally legit in some Test Pilot add-on or some chunk of Firefox code to do

  Weave.Sync.whatever.bumpMyScore();

even if that happens before our timed Sync activation; the caller shouldn't have to figure out if Sync is done starting up when we don't expose a promise on which to wait. See below...
 
> Richard, do you have insights here? ISTM the nextSync mechanism is broken
> here (ie, that in the typical case, Sync always runs at startup regardless
> of when the last sync actually was). The scheduler code is quite a mess, and
> it seems the easiest thing to do it to have that autoConnect code always
> schedule a sync for "now", dropping the pretense that nextSync survives
> between runs - that sounds much easier than trying to fix the code to match
> the apparent intent. WDYT?

I suspect that the roots of this run all the way down to Bug 584771. That's actually one way to fix this: if Sync's init always happens ASAP, the window for this kind of thing narrows.

But IMO the ideal thing to do is to make nextSync correctly persist, with Sync ready to use as soon as it's touched. Doing so probably involves ripping out the rest of autoConnect and friends -- that whole Sync connect/login lifecycle stuff that we partly got rid of years ago. The next sync timestamp always then lives in prefs, and both the app itself and an add-on can happily lazy-load Sync and try to schedule another sync, and whichever one is soonest will win.

Fixing this bug and Bug 584771 would go a long way to improving a bunch of things: Bug 1170916, and the bug-I-can't-find for missing changes that occur soon after startup.

Comment 18

[jeremy9856]

Hello,

Any news on this problem ?

Comment 19

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

(In reply to jeremy9856 from comment #18)
> Any news on this problem ?

We haven't prioritized this as greasemonkey is the only thing we are aware of that caused the problem, but it has been fixed by greasemonkey.

Comment 20

[jeremy9856]

Ok, it's just to be sure that will not be forgotten ;)

Comment 21

[jeremy9856]

Even when there is no delay for the sync to start, I noticed that some thing can be missed. If you add or remove a bookmark before the sync have started the bookmark will never be taken into account, even if you manually trigger the sync.

The sync should start before the user can do anything or, much better, the sync should not miss some things afterwards even if it happen before the first sync.

Comment 22

[jeremy9856]

Well I think the priority of this problem should be revised because as I said, when there is no delay for the sync to start, and by this I mean with a clean profile without any add-on, some thing can be missed.

Again, as I said, if you add or remove a bookmark before the sync have started the bookmark will never be taken into account, even if you manually trigger the sync.

The sync should start before the user can do anything or, much better, the sync should not miss some things afterwards even if it happen before the first sync.

Thanks !

Comment 23

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

(In reply to jeremy9856 from comment #21)
> Even when there is no delay for the sync to start, I noticed that some thing
> can be missed. If you add or remove a bookmark before the sync have started
> the bookmark will never be taken into account, even if you manually trigger
> the sync.

Note that the problem you describe there is a different bug that has been fixed in Firefox 53. The problem initially described in this bug was caused by Greasemonkey and has already been fixed by them.

Comment 24

[jeremy9856]

> Note that the problem you describe there is a different bug that has been fixed in Firefox 53.

You are right, it's a different problem. Happy to ear that has been fixed in F53.
Can you point me the bug id please ? Thanks !

> The problem initially described in this bug was caused by Greasemonkey and has already been fixed by them.

It don't seem to be fixed in Greasemonkey yet

https://github.com/greasemonkey/greasemonkey/issues/2414

Comment 25

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

(In reply to jeremy9856 from comment #24)
> > Note that the problem you describe there is a different bug that has been fixed in Firefox 53.
> 
> You are right, it's a different problem. Happy to ear that has been fixed in
> F53.
> Can you point me the bug id please ? Thanks !

Bug 1258127.

> > The problem initially described in this bug was caused by Greasemonkey and has already been fixed by them.
> 
> It don't seem to be fixed in Greasemonkey yet
> 
> https://github.com/greasemonkey/greasemonkey/issues/2414

Oops - I must have misread the above.

Comment 26

[jeremy9856]

Just to let you know that it won't be fixed in Greasemonkey as the bug report indicate

https://github.com/greasemonkey/greasemonkey/issues/2414

Comment 27

[Anthony Lieuallen]

Indeed; Firefox 57 makes this issue obsolete.  All my available time is going into building a WebExt compatible version of Greasemonkey now.  (And if I understand the root bug, Greasemonkey's relation to it only happens in a non-default state, of a setting exposed only by about:config.)

Comment 28

[jeremy9856]

Ok, thank you !