1064122 - Long-overdue syncs don't occur when prompted

Status: RESOLVED WORKSFORME

(Firefox :: Sync, defect)

Description

[Richard Newman [:rnewman]]

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.

Comment 1

[Richard Newman [:rnewman]]

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.

Comment 2

[Richard Newman [:rnewman]]

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/1.37.0.20140906030204.
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.

Comment 3

[Richard Newman [:rnewman]]

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?

Comment 4

[Richard Newman [:rnewman]]

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.

Comment 5

[Richard Newman [:rnewman]]

And for sleep/wake, we have wake_notification. So let's do that.

Comment 6

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

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/1.58.0.20170616005401.desktop
... and we are syncing.