953282 - Sync scheduling is wrong

Status: VERIFIED FIXED

(Firefox :: Sync, defect, P1)

Description

[Richard Newman [:rnewman]]

1388114699995	Sync.SyncScheduler	DEBUG	Global Score threshold hit, triggering sync.
1388114699996	Sync.Service	INFO	Starting sync at 2013-12-26 19:24:59
1388114700345	Sync.Synchronizer	DEBUG	Refreshing client list.
1388114700347	Sync.Synchronizer	INFO	Updating enabled engines: 4 clients.
1388114701178	Sync.Status	DEBUG	Status.sync: success.sync => success.sync
1388114701178	Sync.Status	DEBUG	Status.service: success.status_ok => success.status_ok
1388114701179	Sync.Synchronizer	INFO	Sync completed at 2013-12-26 19:25:01 after 1.18 secs.
1388114701179	Sync.SyncScheduler	DEBUG	Next sync in 3600000 ms.



I have four clients, but I'm only syncing every hour. That implies that we're hitting the idle logic, not the active logic. This is happening even when I trigger an instant sync by bookmarking an item, so I'm definitely not idle. Something is screwing up in monitoring of idle state, perhaps.

Further, my last sync last night set my next sync interval to one hour later, but it didn't sync again until I manually told it to, 15 hours later:

 success-1388115528096.txt 	280 KB 	2013-12-26 	Dec 26 19:38:48
   1388115528096	Sync.Synchronizer	INFO	Sync completed at 2013-12-26 19:38:48 after 1.16 secs.
   1388115528096	Sync.SyncScheduler	DEBUG	Next sync in 3600000 ms.

 success-1388168917097.txt 	352 KB 	2013-12-27 	Dec 27 10:28:37 

so apparently that half of instant sync isn't working -- I picked the machine up and did my usual browsing for more than five minutes, ultimately creating a new window and hitting "Sync Now" to pick up tabs I'd sent to this machine 12 hours previously. They arrived, which is a pretty obvious indicator that no syncing had occurred.

Comment 1

[Richard Newman [:rnewman]]

Further testing (with trace logging for `main`) reveals that we're able to transition into idle, but we never transition to non-idle. That is: once you leave your machine idle for long enough, you'll be stuck syncing once per hour until you restart Firefox.

Comment 2

[Richard Newman [:rnewman]]

Oh for fuck's sake.

"and receive a 'back' (Gecko 3 to 15) or 'active' (Gecko 16+) notification when the user starts using their computer again."

https://developer.mozilla.org/en-US/docs/XPCOM_Interface_Reference/nsIIdleService

Comment 3

[Richard Newman [:rnewman]]

Attachment: Proposed patch. v1

Try:

https://tbpl.mozilla.org/?tree=Try&rev=3baa64a08656

Comment 4

[Gregory Szorc [:gps]]

Comment on attachment 8351601 [details] [diff] [review]
Proposed patch. v1

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

*head bang desk*

Yuck. And right here we have an excellent example on why the "weak" API provided by named observers lends itself to footguns and future bugs. If we performed notification handling via "strong" APIs like function calls (e.g. idleService.onIdleBack(callback)), these kinds of bugs would likely be less frequent since underlying API changes would result in things like exceptions due to accessing missing properties. Even a simple "registry" of known observer "channels" would help.

That being said, given the nature of the underlying system being tested, chances are a mock would be required somewhere. And mocking is prone to being out of sync with the underlying implementation. I guess one way to mitigate that would be for the idle service "module" to provide a mechanism guaranteed to test idle service behavior accurately. I'd love to see a followup bug to track better testing of the idle service. So many JS components rely on idle service and from what I've seen, idle service behavior in these components isn't exactly tested robustly IMO.

This bug is just painful no matter how you look at it. Nice catch.

Comment 5

[Richard Newman [:rnewman]]

Thanks for the quick review, Greg!

> This bug is just painful no matter how you look at it. Nice catch.

And this is why we have super-review. Which Bug 715041 apparently didn't get, despite changing a public API. bsurender, please do things differently next time!

Comment 6

[Richard Newman [:rnewman]]

https://hg.mozilla.org/integration/fx-team/rev/bff6343a2066

Comment 7

[Richard Newman [:rnewman]]

Comment on attachment 8351601 [details] [diff] [review]
Proposed patch. v1

[Approval Request Comment]
Bug caused by (feature/regressing bug #): 
  Bug 715041

User impact if declined: 
  Once a machine enters idle state, Sync will only sync once per hour, rather than re-entering the frequent syncing state when they return. Sent tabs, history items, bookmarks, etc. won't appear as frequently as they should. Frustration ensues.

Testing completed (on m-c, etc.):
  Just landed.
 
Risk to taking this patch (and alternatives if risky): 
  None; it's changing the string that an observer looks for. Worst-case scenario is that nothing happens; best case is that Instant Sync works again, as it did between Fx7 and Fx16.

String or IDL/UUID changes made by this patch:
  None.

Comment 8

[Phil Ringnalda (:philor)]

https://hg.mozilla.org/mozilla-central/rev/bff6343a2066

Comment 9

[Richard Newman [:rnewman]]

This is working for me in my regular Nightly profile.

1388725295049   Sync.SyncScheduler      TRACE   Handling idle
1388725295049   Sync.SyncScheduler      TRACE   We're idle.
1388725295049   Sync.SyncScheduler      TRACE   Adjusting syncInterval to idleInterval.
1388725470513   Sync.SyncScheduler      TRACE   Handling active
1388725470513   Sync.SyncScheduler      TRACE   Received notification that we're back from idle.
1388725470614   Sync.SyncScheduler      TRACE   Genuine return from idle. Syncing.
1388725470614   Sync.SyncScheduler      TRACE   There's already a sync scheduled in 115386 ms.
1388725470614   Sync.SyncScheduler      TRACE   Requested sync should happen right away.
1388725470618   Sync.Service    DEBUG   User-Agent: Firefox/29.0a1 FxSync/1.31.0.20131230072341.
1388725470618   Sync.Service    INFO    Starting sync at 2014-01-02 21:04:30

Comment 10

[bhavana bajaj [:bajaj]]

Comment on attachment 8351601 [details] [diff] [review]
Proposed patch. v1

Thanks for the help with verification here :rnewman. Given the risk analysis this looks good to land. In addition if this needs more testing please add qawanted and help with a few pointers on test cases so this is on QA's radar for verification.

Comment 11

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/9eee77743c8c
https://hg.mozilla.org/releases/mozilla-beta/rev/215140a367e0

Not sure if this is a wontfix for esr24 or not, but it's certainly going to need an approval request if it is desired for there as well.

Comment 12

[James Bonacci [:jbonacci]]

Note the [qa+] 
;-)

This is already on my list to check once I get back from PTO on Jan 6.

Comment 13

[Daniel Veditz [:dveditz]]

Is this needed on ESR-24? Sounds like it's just degraded service not completely broken so maybe there aren't enough users there (with Sync accounts) to matter.

Comment 14

[Richard Newman [:rnewman]]

(In reply to Daniel Veditz [:dveditz] from comment #13)
> Is this needed on ESR-24? Sounds like it's just degraded service not
> completely broken so maybe there aren't enough users there (with Sync
> accounts) to matter.

I don't know how the process works for fixes on ESR. It's a small fix that I would support shipping there.

Comment 15

[Lukas Blakk [:lsblakk] use ?needinfo]

it doesn't meet ESR landing criteria and we're not hearing a lot from users about issues here, so wontfixing unless the latter changes.