Long-overdue syncs don't occur when prompted

RESOLVED WORKSFORME

Status

Cloud Services
Firefox Sync: Backend
RESOLVED WORKSFORME
3 years ago
4 months ago

People

(Reporter: rnewman, Unassigned)

Tracking

Firefox Tracking Flags

(Not tracked)

Details

(Whiteboard: [qa+])

(Reporter)

Description

3 years ago
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.
(Reporter)

Comment 1

3 years ago
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.
(Reporter)

Comment 2

3 years ago
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.
(Reporter)

Comment 3

3 years ago
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?
(Reporter)

Comment 4

3 years ago
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.
(Reporter)

Comment 5

3 years ago
And for sleep/wake, we have wake_notification. So let's do that.
(Reporter)

Updated

3 years ago
Blocks: 1064132
(Reporter)

Updated

3 years ago
Summary: Instant Sync is broken → Long-overdue syncs don't occur when prompted
Whiteboard: [qa+]
Flags: needinfo?(markh)
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.
Status: NEW → RESOLVED
Last Resolved: 4 months ago
Flags: needinfo?(markh)
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.