When I wake my Mac after being asleep for more than half an hour: 1410139949318 Sync.SyncScheduler TRACE Handling weave:engine:score:updated 1410139949330 Sync.SyncScheduler TRACE Handling weave:engine:score:updated 1410139949431 Sync.SyncScheduler TRACE clients: score: 0 1410139949431 Sync.SyncScheduler TRACE bookmarks: score: 0 1410139949431 Sync.SyncScheduler TRACE forms: score: 0 1410139949431 Sync.SyncScheduler TRACE history: score: 0 1410139949431 Sync.SyncScheduler TRACE passwords: score: 0 1410139949432 Sync.SyncScheduler TRACE prefs: score: 0 1410139949432 Sync.SyncScheduler TRACE tabs: score: 2 1410139949432 Sync.SyncScheduler TRACE Global score updated: 23 1410139949432 Sync.SyncScheduler TRACE _checkSync returned "". 1410139949432 Sync.SyncScheduler TRACE There's already a sync scheduled in -6274432 ms. 1410139949432 Sync.SyncScheduler TRACE Ignoring scheduling request for next sync in 600000 ms. I have to trigger a sync manually: 1410139954036 Sync.Status DEBUG Status.service: success.status_ok => success.status_ok 1410139955671 Sync.ErrorHandler DEBUG Beginning user-triggered sync. As far as I know, this has been the case for Quite Some Time.
It's also worth noting: I have `main` logging set to `Trace`, but I don't see any of the SyncScheduler idle-related logging that one would expect.
Out of 861 logged syncs in my primary profile, I have 129 "idle" and 129 "active" notifications. So it's not that we're not receiving nsIIdleService notifications -- we are. And when we do, we do sync: 1410131272070 Sync.SyncScheduler TRACE Handling active 1410131272070 Sync.SyncScheduler TRACE Received notification that we're back from idle. 1410131272171 Sync.SyncScheduler TRACE Genuine return from idle. Syncing. 1410131272171 Sync.SyncScheduler TRACE There's already a sync scheduled in 3281829 ms. 1410131272171 Sync.SyncScheduler TRACE Requested sync should happen right away. 1410131272172 Sync.Service DEBUG User-Agent: Firefox/35.0a1 FxSync/126.96.36.19940906030204. 1410131272172 Sync.Service INFO Starting sync at 2014-09-07 16:07:52 1410131272172 Sync.Service TRACE In sync: no need to login. 1410131272172 Sync.Service TRACE Event: weave:service:sync:start ... so... what's going on in that log? The log is complete from moment of wake.
My speculation: we *should* have received an idle notification in this case. We didn't. The only log output right then was from two tabs changing (presumably Facebook and Twitter changing their unread counts). Those bumped the score, which caused checkSyncStatus to run. So, two bugs: * When we hit checkSyncStatus and a sync is overdue, SYNC! * Why is the idle service not telling us that the user returned from idle?
This might be down to a misinterpretation of the idle service. I *think* Sync is expecting to get an "active" message when the user wakes the machine from sleep. (On Mac we used to get these _all the time_ -- Bug 691988.) I *think* the idle service will only send an "active" if it previously sent an "idle". What's happening in the first log is that the machine was active when I put it to sleep, so it's active when it wakes up. It's pure luck that the score bump caused a sync. Even though the machine was asleep for an hour and a half, to an idle observer nothing happened.
And for sleep/wake, we have wake_notification. So let's do that.
I can no longer reproduce this - I instrumented policies.js to log when the sync was caused by the timer firing, and it fired as expected. I expect this was fixed by bug 1178890, before which timers were apparently rescheduled with their *initial* timeout rather than with a newly calculated timeout based on how long was actually remaining. My log output: 498107571032 Sync.SyncScheduler TRACE Handling wake_notification 1498107571032 Sync.SyncScheduler DEBUG Woke from sleep. 1498107571033 Sync.SyncScheduler DEBUG More than 1 client. Will sync in 5s. 1498107571034 Sync.SyncScheduler TRACE There's already a sync scheduled in -263034 ms. 1498107571034 Sync.SyncScheduler TRACE Ignoring scheduling request for next sync in 5000 ms. TIMER FIRED <-- this is the hack I made to dump when the timer fired. 1498107587242 Sync.Service DEBUG User-Agent: Firefox/56.0a1 (Intel Mac OS X 10.12) FxSync/188.8.131.5270616005401.desktop ... and we are syncing.