1 // Copyright (c) 2012 The Chromium Authors. All rights reserved.
2 // Use of this source code is governed by a BSD-style license that can be
3 // found in the LICENSE file.
4 
5 #include "components/sync/engine_impl/sync_scheduler_impl.h"
6 
7 #include <cstring>
8 #include <utility>
9 
10 #include "base/bind.h"
11 #include "base/location.h"
12 #include "base/logging.h"
13 #include "base/metrics/histogram_macros.h"
14 #include "base/rand_util.h"
15 #include "base/sequenced_task_runner.h"
16 #include "base/threading/platform_thread.h"
17 #include "base/threading/sequenced_task_runner_handle.h"
18 #include "components/sync/base/logging.h"
19 #include "components/sync/base/model_type.h"
20 #include "components/sync/engine/sync_engine_switches.h"
21 #include "components/sync/engine_impl/backoff_delay_provider.h"
22 #include "components/sync/protocol/sync.pb.h"
23 
24 using base::TimeDelta;
25 using base::TimeTicks;
26 
27 namespace syncer {
28 
29 namespace {
30 
IsConfigRelatedUpdateOriginValue(sync_pb::SyncEnums::GetUpdatesOrigin origin)31 bool IsConfigRelatedUpdateOriginValue(
32     sync_pb::SyncEnums::GetUpdatesOrigin origin) {
33   switch (origin) {
34     case sync_pb::SyncEnums::RECONFIGURATION:
35     case sync_pb::SyncEnums::MIGRATION:
36     case sync_pb::SyncEnums::NEW_CLIENT:
37     case sync_pb::SyncEnums::NEWLY_SUPPORTED_DATATYPE:
38     case sync_pb::SyncEnums::PROGRAMMATIC:
39       return true;
40     case sync_pb::SyncEnums::UNKNOWN_ORIGIN:
41     case sync_pb::SyncEnums::PERIODIC:
42     case sync_pb::SyncEnums::GU_TRIGGER:
43     case sync_pb::SyncEnums::RETRY:
44       return false;
45   }
46   NOTREACHED();
47   return false;
48 }
49 
ShouldRequestEarlyExit(const SyncProtocolError & error)50 bool ShouldRequestEarlyExit(const SyncProtocolError& error) {
51   switch (error.error_type) {
52     case SYNC_SUCCESS:
53     case MIGRATION_DONE:
54     case THROTTLED:
55     case TRANSIENT_ERROR:
56     case PARTIAL_FAILURE:
57       return false;
58     case NOT_MY_BIRTHDAY:
59     case CLIENT_DATA_OBSOLETE:
60     case CLEAR_PENDING:
61     case DISABLED_BY_ADMIN:
62     case ENCRYPTION_OBSOLETE:
63       // If we send terminate sync early then |sync_cycle_ended| notification
64       // would not be sent. If there were no actions then |ACTIONABLE_ERROR|
65       // notification wouldnt be sent either. Then the UI layer would be left
66       // waiting forever. So assert we would send something.
67       DCHECK_NE(error.action, UNKNOWN_ACTION);
68       return true;
69     // Make UNKNOWN_ERROR a NOTREACHED. All the other error should be explicitly
70     // handled.
71     case UNKNOWN_ERROR:
72       // TODO(crbug.com/1081266): This NOTREACHED is questionable because the
73       // sync server can cause it.
74       NOTREACHED();
75       return false;
76   }
77   return false;
78 }
79 
IsActionableError(const SyncProtocolError & error)80 bool IsActionableError(const SyncProtocolError& error) {
81   return (error.action != UNKNOWN_ACTION);
82 }
83 
84 #define ENUM_CASE(x) \
85   case x:            \
86     return #x;       \
87     break;
88 
89 }  // namespace
90 
ConfigurationParams()91 ConfigurationParams::ConfigurationParams()
92     : origin(sync_pb::SyncEnums::UNKNOWN_ORIGIN) {}
93 
ConfigurationParams(sync_pb::SyncEnums::GetUpdatesOrigin origin,ModelTypeSet types_to_download,base::OnceClosure ready)94 ConfigurationParams::ConfigurationParams(
95     sync_pb::SyncEnums::GetUpdatesOrigin origin,
96     ModelTypeSet types_to_download,
97     base::OnceClosure ready)
98     : origin(origin),
99       types_to_download(types_to_download),
100       ready_task(std::move(ready)) {
101   DCHECK(!ready_task.is_null());
102 }
103 
104 ConfigurationParams::ConfigurationParams(ConfigurationParams&&) = default;
105 
106 ConfigurationParams& ConfigurationParams::operator=(ConfigurationParams&&) =
107     default;
108 
109 ConfigurationParams::~ConfigurationParams() = default;
110 
111 // Helper macros to log with the syncer thread name; useful when there
112 // are multiple syncer threads involved.
113 
114 #define SDVLOG(verbose_level) DVLOG(verbose_level) << name_ << ": "
115 
116 #define SDVLOG_LOC(from_here, verbose_level) \
117   DVLOG_LOC(from_here, verbose_level) << name_ << ": "
118 
SyncSchedulerImpl(const std::string & name,BackoffDelayProvider * delay_provider,SyncCycleContext * context,Syncer * syncer,bool ignore_auth_credentials)119 SyncSchedulerImpl::SyncSchedulerImpl(const std::string& name,
120                                      BackoffDelayProvider* delay_provider,
121                                      SyncCycleContext* context,
122                                      Syncer* syncer,
123                                      bool ignore_auth_credentials)
124     : name_(name),
125       started_(false),
126       syncer_poll_interval_seconds_(context->poll_interval()),
127       mode_(CONFIGURATION_MODE),
128       delay_provider_(delay_provider),
129       syncer_(syncer),
130       cycle_context_(context),
131       next_sync_cycle_job_priority_(NORMAL_PRIORITY),
132       ignore_auth_credentials_(ignore_auth_credentials) {}
133 
~SyncSchedulerImpl()134 SyncSchedulerImpl::~SyncSchedulerImpl() {
135   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
136 
137   Stop();
138 }
139 
OnCredentialsUpdated()140 void SyncSchedulerImpl::OnCredentialsUpdated() {
141   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
142 
143   // If this is the first time we got credentials, or we were previously in an
144   // auth error state, then try connecting to the server now.
145   HttpResponse::ServerConnectionCode server_status =
146       cycle_context_->connection_manager()->server_status();
147   if (server_status == HttpResponse::NONE ||
148       server_status == HttpResponse::SYNC_AUTH_ERROR) {
149     OnServerConnectionErrorFixed();
150   }
151 }
152 
OnConnectionStatusChange(network::mojom::ConnectionType type)153 void SyncSchedulerImpl::OnConnectionStatusChange(
154     network::mojom::ConnectionType type) {
155   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
156 
157   if (type != network::mojom::ConnectionType::CONNECTION_NONE &&
158       HttpResponse::CONNECTION_UNAVAILABLE ==
159           cycle_context_->connection_manager()->server_status()) {
160     // Optimistically assume that the connection is fixed and try
161     // connecting.
162     OnServerConnectionErrorFixed();
163   }
164 }
165 
OnServerConnectionErrorFixed()166 void SyncSchedulerImpl::OnServerConnectionErrorFixed() {
167   // There could be a pending nudge or configuration job in several cases:
168   //
169   // 1. We're in exponential backoff.
170   // 2. We're silenced / throttled.
171   // 3. A nudge was saved previously due to not having a valid access token.
172   // 4. A nudge was scheduled + saved while in configuration mode.
173   //
174   // In all cases except (2), we want to retry contacting the server. We
175   // call TryCanaryJob to achieve this, and note that nothing -- not even a
176   // canary job -- can bypass a THROTTLED WaitInterval. The only thing that
177   // has the authority to do that is the Unthrottle timer.
178   TryCanaryJob();
179 }
180 
Start(Mode mode,base::Time last_poll_time)181 void SyncSchedulerImpl::Start(Mode mode, base::Time last_poll_time) {
182   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
183 
184   std::string thread_name = base::PlatformThread::GetName();
185   if (thread_name.empty())
186     thread_name = "<Main thread>";
187   SDVLOG(2) << "Start called from thread " << thread_name << " with mode "
188             << GetModeString(mode);
189   if (!started_) {
190     started_ = true;
191     SendInitialSnapshot();
192   }
193 
194   DCHECK(syncer_);
195 
196   Mode old_mode = mode_;
197   mode_ = mode;
198   base::Time now = base::Time::Now();
199 
200   // Only adjust the poll reset time if it was valid and in the past.
201   if (!last_poll_time.is_null() && last_poll_time <= now) {
202     // Convert from base::Time to base::TimeTicks. The reason we use Time
203     // for persisting is that TimeTicks can stop making forward progress when
204     // the machine is suspended. This implies that on resume the client might
205     // actually have miss the real poll, unless the client is restarted.
206     // Fixing that would require using an AlarmTimer though, which is only
207     // supported on certain platforms.
208     last_poll_reset_ =
209         TimeTicks::Now() -
210         (now - ComputeLastPollOnStart(last_poll_time, GetPollInterval(), now));
211   }
212 
213   if (old_mode != mode_ && mode_ == NORMAL_MODE) {
214     // We just got back to normal mode.  Let's try to run the work that was
215     // queued up while we were configuring.
216 
217     AdjustPolling(UPDATE_INTERVAL);  // Will kick start poll timer if needed.
218 
219     // Update our current time before checking IsRetryRequired().
220     nudge_tracker_.SetSyncCycleStartTime(TimeTicks::Now());
221     if (nudge_tracker_.IsSyncRequired(GetEnabledAndUnblockedTypes()) &&
222         CanRunNudgeJobNow(NORMAL_PRIORITY)) {
223       TrySyncCycleJob();
224     }
225   }
226 }
227 
228 // static
ComputeLastPollOnStart(base::Time last_poll,base::TimeDelta poll_interval,base::Time now)229 base::Time SyncSchedulerImpl::ComputeLastPollOnStart(
230     base::Time last_poll,
231     base::TimeDelta poll_interval,
232     base::Time now) {
233   if (base::FeatureList::IsEnabled(switches::kSyncResetPollIntervalOnStart)) {
234     return now;
235   }
236   // Handle immediate polls on start-up separately.
237   if (last_poll + poll_interval <= now) {
238     // Doing polls on start-up is generally a risk as other bugs in Chrome
239     // might cause start-ups -- potentially synchronized to a specific time.
240     // (think about a system timer waking up Chrome).
241     // To minimize that risk, we randomly delay polls on start-up to a max
242     // of 1% of the poll interval. Assuming a poll rate of 4h, that's at
243     // most 2.4 mins.
244     base::TimeDelta random_delay = base::RandDouble() * 0.01 * poll_interval;
245     return now - (poll_interval - random_delay);
246   }
247   return last_poll;
248 }
249 
GetEnabledAndUnblockedTypes()250 ModelTypeSet SyncSchedulerImpl::GetEnabledAndUnblockedTypes() {
251   ModelTypeSet enabled_types = cycle_context_->GetEnabledTypes();
252   ModelTypeSet enabled_protocol_types =
253       Intersection(ProtocolTypes(), enabled_types);
254   ModelTypeSet blocked_types = nudge_tracker_.GetBlockedTypes();
255   return Difference(enabled_protocol_types, blocked_types);
256 }
257 
SendInitialSnapshot()258 void SyncSchedulerImpl::SendInitialSnapshot() {
259   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
260 
261   SyncCycleEvent event(SyncCycleEvent::STATUS_CHANGED);
262   event.snapshot = SyncCycle(cycle_context_, this).TakeSnapshot();
263   for (auto& observer : *cycle_context_->listeners())
264     observer.OnSyncCycleEvent(event);
265 }
266 
ScheduleConfiguration(ConfigurationParams params)267 void SyncSchedulerImpl::ScheduleConfiguration(ConfigurationParams params) {
268   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
269   DCHECK(IsConfigRelatedUpdateOriginValue(params.origin));
270   DCHECK_EQ(CONFIGURATION_MODE, mode_);
271   DCHECK(!params.ready_task.is_null());
272   DCHECK(started_) << "Scheduler must be running to configure.";
273   SDVLOG(2) << "Reconfiguring syncer.";
274 
275   // Only one configuration is allowed at a time. Verify we're not waiting
276   // for a pending configure job.
277   DCHECK(!pending_configure_params_);
278 
279   // Only reconfigure if we have types to download.
280   if (!params.types_to_download.Empty()) {
281     pending_configure_params_ =
282         std::make_unique<ConfigurationParams>(std::move(params));
283     TrySyncCycleJob();
284   } else {
285     SDVLOG(2) << "No change in routing info, calling ready task directly.";
286     std::move(params.ready_task).Run();
287   }
288 }
289 
CanRunJobNow(JobPriority priority)290 bool SyncSchedulerImpl::CanRunJobNow(JobPriority priority) {
291   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
292 
293   if (IsGlobalThrottle()) {
294     SDVLOG(1) << "Unable to run a job because we're throttled.";
295     return false;
296   }
297 
298   if (IsGlobalBackoff() && priority != CANARY_PRIORITY) {
299     SDVLOG(1) << "Unable to run a job because we're backing off.";
300     return false;
301   }
302 
303   if (!ignore_auth_credentials_ &&
304       cycle_context_->connection_manager()->HasInvalidAccessToken()) {
305     SDVLOG(1) << "Unable to run a job because we have no valid access token.";
306     return false;
307   }
308 
309   return true;
310 }
311 
CanRunNudgeJobNow(JobPriority priority)312 bool SyncSchedulerImpl::CanRunNudgeJobNow(JobPriority priority) {
313   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
314 
315   if (!CanRunJobNow(priority)) {
316     SDVLOG(1) << "Unable to run a nudge job right now";
317     return false;
318   }
319 
320   const ModelTypeSet enabled_types = cycle_context_->GetEnabledTypes();
321   if (nudge_tracker_.GetBlockedTypes().HasAll(enabled_types)) {
322     SDVLOG(1) << "Not running a nudge because we're fully type throttled or "
323                  "backed off.";
324     return false;
325   }
326 
327   if (mode_ != NORMAL_MODE) {
328     SDVLOG(1) << "Not running nudge because we're not in normal mode.";
329     return false;
330   }
331 
332   return true;
333 }
334 
ScheduleLocalNudge(ModelTypeSet types,const base::Location & nudge_location)335 void SyncSchedulerImpl::ScheduleLocalNudge(
336     ModelTypeSet types,
337     const base::Location& nudge_location) {
338   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
339   DCHECK(!types.Empty());
340 
341   SDVLOG_LOC(nudge_location, 2) << "Scheduling sync because of local change to "
342                                 << ModelTypeSetToString(types);
343   TimeDelta nudge_delay = nudge_tracker_.RecordLocalChange(types);
344   ScheduleNudgeImpl(nudge_delay, nudge_location);
345 }
346 
ScheduleLocalRefreshRequest(ModelTypeSet types,const base::Location & nudge_location)347 void SyncSchedulerImpl::ScheduleLocalRefreshRequest(
348     ModelTypeSet types,
349     const base::Location& nudge_location) {
350   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
351   DCHECK(!types.Empty());
352 
353   SDVLOG_LOC(nudge_location, 2)
354       << "Scheduling sync because of local refresh request for "
355       << ModelTypeSetToString(types);
356   TimeDelta nudge_delay = nudge_tracker_.RecordLocalRefreshRequest(types);
357   ScheduleNudgeImpl(nudge_delay, nudge_location);
358 }
359 
ScheduleInvalidationNudge(ModelType model_type,std::unique_ptr<InvalidationInterface> invalidation,const base::Location & nudge_location)360 void SyncSchedulerImpl::ScheduleInvalidationNudge(
361     ModelType model_type,
362     std::unique_ptr<InvalidationInterface> invalidation,
363     const base::Location& nudge_location) {
364   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
365   DCHECK(!syncer_->IsSyncing());
366 
367   SDVLOG_LOC(nudge_location, 2)
368       << "Scheduling sync because we received invalidation for "
369       << ModelTypeToString(model_type);
370   TimeDelta nudge_delay = nudge_tracker_.RecordRemoteInvalidation(
371       model_type, std::move(invalidation));
372   ScheduleNudgeImpl(nudge_delay, nudge_location);
373 }
374 
ScheduleInitialSyncNudge(ModelType model_type)375 void SyncSchedulerImpl::ScheduleInitialSyncNudge(ModelType model_type) {
376   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
377   DCHECK(!syncer_->IsSyncing());
378 
379   SDVLOG(2) << "Scheduling non-blocking initial sync for "
380             << ModelTypeToString(model_type);
381   nudge_tracker_.RecordInitialSyncRequired(model_type);
382   ScheduleNudgeImpl(TimeDelta::FromSeconds(0), FROM_HERE);
383 }
384 
385 // TODO(zea): Consider adding separate throttling/backoff for datatype
386 // refresh requests.
ScheduleNudgeImpl(const TimeDelta & delay,const base::Location & nudge_location)387 void SyncSchedulerImpl::ScheduleNudgeImpl(
388     const TimeDelta& delay,
389     const base::Location& nudge_location) {
390   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
391 
392   if (!started_) {
393     SDVLOG_LOC(nudge_location, 2)
394         << "Dropping nudge, scheduler is not running.";
395     return;
396   }
397 
398   SDVLOG_LOC(nudge_location, 2) << "In ScheduleNudgeImpl with delay "
399                                 << delay.InMilliseconds() << " ms";
400 
401   if (!CanRunNudgeJobNow(NORMAL_PRIORITY))
402     return;
403 
404   if (!IsEarlierThanCurrentPendingJob(delay)) {
405     // Old job arrives sooner than this one.  Don't reschedule it.
406     return;
407   }
408 
409   // Either there is no existing nudge in flight or the incoming nudge should be
410   // made to arrive first (preempt) the existing nudge.  We reschedule in either
411   // case.
412   SDVLOG_LOC(nudge_location, 2) << "Scheduling a nudge with "
413                                 << delay.InMilliseconds() << " ms delay";
414   pending_wakeup_timer_.Start(
415       nudge_location, delay,
416       base::BindOnce(&SyncSchedulerImpl::PerformDelayedNudge,
417                      weak_ptr_factory_.GetWeakPtr()));
418 }
419 
GetModeString(SyncScheduler::Mode mode)420 const char* SyncSchedulerImpl::GetModeString(SyncScheduler::Mode mode) {
421   switch (mode) {
422     ENUM_CASE(CONFIGURATION_MODE);
423     ENUM_CASE(NORMAL_MODE);
424   }
425   return "";
426 }
427 
ForceShortNudgeDelayForTest()428 void SyncSchedulerImpl::ForceShortNudgeDelayForTest() {
429   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
430   // Set the default nudge delay to 0 because the default is used as a floor
431   // for override values, and we don't want the below override to be ignored.
432   nudge_tracker_.SetDefaultNudgeDelay(TimeDelta::FromMilliseconds(0));
433   // Only protocol types can have their delay customized.
434   const ModelTypeSet protocol_types = syncer::ProtocolTypes();
435   const base::TimeDelta short_nudge_delay = TimeDelta::FromMilliseconds(1);
436   std::map<ModelType, base::TimeDelta> nudge_delays;
437   for (ModelType type : protocol_types) {
438     nudge_delays[type] = short_nudge_delay;
439   }
440   nudge_tracker_.OnReceivedCustomNudgeDelays(nudge_delays);
441   // We should prevent further changing of nudge delays so if we use real server
442   // for integration test then server is not able to increase delays.
443   force_short_nudge_delay_for_test_ = true;
444 }
445 
DoNudgeSyncCycleJob(JobPriority priority)446 void SyncSchedulerImpl::DoNudgeSyncCycleJob(JobPriority priority) {
447   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
448   DCHECK(CanRunNudgeJobNow(priority));
449 
450   ModelTypeSet types = GetEnabledAndUnblockedTypes();
451   DVLOG(2) << "Will run normal mode sync cycle with types "
452            << ModelTypeSetToString(types);
453   SyncCycle cycle(cycle_context_, this);
454   bool success = syncer_->NormalSyncShare(types, &nudge_tracker_, &cycle);
455 
456   if (success) {
457     // That cycle took care of any outstanding work we had.
458     SDVLOG(2) << "Nudge succeeded.";
459     // Note that some types might have become blocked (throttled) during the
460     // cycle. NudgeTracker knows of that, and won't clear any "outstanding work"
461     // flags for these types.
462     // TODO(crbug.com/930074): Consider renaming this method to
463     // RecordSuccessfulSyncCycleIfNotBlocked.
464     nudge_tracker_.RecordSuccessfulSyncCycle(types);
465     HandleSuccess();
466 
467     // If this was a canary, we may need to restart the poll timer (the poll
468     // timer may have fired while the scheduler was in an error state, ignoring
469     // the poll).
470     if (!poll_timer_.IsRunning()) {
471       SDVLOG(1) << "Canary succeeded, restarting polling.";
472       AdjustPolling(UPDATE_INTERVAL);
473     }
474   } else {
475     HandleFailure(cycle.status_controller().model_neutral_state());
476   }
477 }
478 
DoConfigurationSyncCycleJob(JobPriority priority)479 void SyncSchedulerImpl::DoConfigurationSyncCycleJob(JobPriority priority) {
480   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
481   DCHECK_EQ(mode_, CONFIGURATION_MODE);
482   DCHECK(pending_configure_params_ != nullptr);
483 
484   if (!CanRunJobNow(priority)) {
485     SDVLOG(2) << "Unable to run configure job right now.";
486     return;
487   }
488 
489   SDVLOG(2) << "Will run configure SyncShare with types "
490             << ModelTypeSetToString(
491                    pending_configure_params_->types_to_download);
492   SyncCycle cycle(cycle_context_, this);
493   bool success =
494       syncer_->ConfigureSyncShare(pending_configure_params_->types_to_download,
495                                   pending_configure_params_->origin, &cycle);
496 
497   if (success) {
498     SDVLOG(2) << "Configure succeeded.";
499     // At this point, the initial sync for the affected types has been
500     // completed. Let the nudge tracker know to avoid any spurious extra
501     // requests; see also crbug.com/926184.
502     nudge_tracker_.RecordInitialSyncDone(
503         pending_configure_params_->types_to_download);
504     std::move(pending_configure_params_->ready_task).Run();
505     pending_configure_params_.reset();
506     HandleSuccess();
507   } else {
508     HandleFailure(cycle.status_controller().model_neutral_state());
509     // Sync cycle might receive response from server that causes scheduler to
510     // stop and draws pending_configure_params_ invalid.
511   }
512 }
513 
HandleSuccess()514 void SyncSchedulerImpl::HandleSuccess() {
515   // If we're here, then we successfully reached the server. End all global
516   // throttle or backoff.
517   wait_interval_.reset();
518 }
519 
HandleFailure(const ModelNeutralState & model_neutral_state)520 void SyncSchedulerImpl::HandleFailure(
521     const ModelNeutralState& model_neutral_state) {
522   if (IsGlobalThrottle()) {
523     SDVLOG(2) << "Was throttled during previous sync cycle.";
524   } else {
525     // TODO(skym): Slightly bizarre, the initial SYNC_AUTH_ERROR seems to
526     // trigger exponential backoff here, although it's immediately retried with
527     // correct credentials, it'd be nice if things were a bit more clean.
528     base::TimeDelta previous_delay =
529         IsGlobalBackoff()
530             ? wait_interval_->length
531             : delay_provider_->GetInitialDelay(model_neutral_state);
532     TimeDelta next_delay = delay_provider_->GetDelay(previous_delay);
533     wait_interval_ = std::make_unique<WaitInterval>(
534         WaitInterval::EXPONENTIAL_BACKOFF, next_delay);
535     SDVLOG(2) << "Sync cycle failed.  Will back off for "
536               << wait_interval_->length.InMilliseconds() << "ms.";
537   }
538 }
539 
DoPollSyncCycleJob()540 void SyncSchedulerImpl::DoPollSyncCycleJob() {
541   SDVLOG(2) << "Polling with types "
542             << ModelTypeSetToString(GetEnabledAndUnblockedTypes());
543   SyncCycle cycle(cycle_context_, this);
544   bool success = syncer_->PollSyncShare(GetEnabledAndUnblockedTypes(), &cycle);
545 
546   // Only restart the timer if the poll succeeded. Otherwise rely on normal
547   // failure handling to retry with backoff.
548   if (success) {
549     AdjustPolling(FORCE_RESET);
550     HandleSuccess();
551   } else {
552     HandleFailure(cycle.status_controller().model_neutral_state());
553   }
554 }
555 
GetPollInterval()556 TimeDelta SyncSchedulerImpl::GetPollInterval() {
557   return syncer_poll_interval_seconds_;
558 }
559 
AdjustPolling(PollAdjustType type)560 void SyncSchedulerImpl::AdjustPolling(PollAdjustType type) {
561   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
562 
563   if (!started_)
564     return;
565 
566   TimeDelta poll_interval = GetPollInterval();
567   TimeDelta poll_delay = poll_interval;
568   const TimeTicks now = TimeTicks::Now();
569 
570   if (type == UPDATE_INTERVAL) {
571     if (!last_poll_reset_.is_null()) {
572       // Override the delay based on the last successful poll time (if it was
573       // set).
574       TimeTicks new_poll_time = poll_interval + last_poll_reset_;
575       poll_delay = new_poll_time - TimeTicks::Now();
576 
577       if (poll_delay < TimeDelta()) {
578         // The desired poll time was in the past, so trigger a poll now (the
579         // timer will post the task asynchronously, so re-entrancy isn't an
580         // issue).
581         poll_delay = TimeDelta();
582       }
583     } else {
584       // There was no previous poll. Keep the delay set to the normal interval,
585       // as if we had just completed a poll.
586       DCHECK_EQ(GetPollInterval(), poll_delay);
587       last_poll_reset_ = now;
588     }
589   } else {
590     // Otherwise just restart the timer.
591     DCHECK_EQ(FORCE_RESET, type);
592     DCHECK_EQ(GetPollInterval(), poll_delay);
593     last_poll_reset_ = now;
594   }
595 
596   SDVLOG(1) << "Updating polling delay to " << poll_delay.InMinutes()
597             << " minutes.";
598 
599   // Adjust poll rate. Start will reset the timer if it was already running.
600   poll_timer_.Start(FROM_HERE, poll_delay, this,
601                     &SyncSchedulerImpl::PollTimerCallback);
602 }
603 
RestartWaiting()604 void SyncSchedulerImpl::RestartWaiting() {
605   NotifyBlockedTypesChanged();
606   if (wait_interval_) {
607     // Global throttling or backoff.
608     if (!IsEarlierThanCurrentPendingJob(wait_interval_->length)) {
609       // We check here because if we do not check here, and we already scheduled
610       // a global unblock job, we will schedule another unblock job which has
611       // same waiting time, then the job will be run later than expected. Even
612       // we did not schedule an unblock job when code reach here, it is ok since
613       // |TrySyncCycleJobImpl| will call this function after the scheduled job
614       // got run.
615       return;
616     }
617     NotifyRetryTime(base::Time::Now() + wait_interval_->length);
618     SDVLOG(2) << "Starting WaitInterval timer of length "
619               << wait_interval_->length.InMilliseconds() << "ms.";
620     if (wait_interval_->mode == WaitInterval::THROTTLED) {
621       pending_wakeup_timer_.Start(
622           FROM_HERE, wait_interval_->length,
623           base::BindOnce(&SyncSchedulerImpl::Unthrottle,
624                          weak_ptr_factory_.GetWeakPtr()));
625     } else {
626       pending_wakeup_timer_.Start(
627           FROM_HERE, wait_interval_->length,
628           base::BindOnce(&SyncSchedulerImpl::ExponentialBackoffRetry,
629                          weak_ptr_factory_.GetWeakPtr()));
630     }
631   } else if (nudge_tracker_.IsAnyTypeBlocked()) {
632     // Per-datatype throttled or backed off.
633     TimeDelta time_until_next_unblock =
634         nudge_tracker_.GetTimeUntilNextUnblock();
635     if (!IsEarlierThanCurrentPendingJob(time_until_next_unblock)) {
636       return;
637     }
638     NotifyRetryTime(base::Time::Now() + time_until_next_unblock);
639     pending_wakeup_timer_.Start(
640         FROM_HERE, time_until_next_unblock,
641         base::BindOnce(&SyncSchedulerImpl::OnTypesUnblocked,
642                        weak_ptr_factory_.GetWeakPtr()));
643   } else {
644     NotifyRetryTime(base::Time());
645   }
646 }
647 
Stop()648 void SyncSchedulerImpl::Stop() {
649   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
650   SDVLOG(2) << "Stop called";
651 
652   // Kill any in-flight method calls.
653   weak_ptr_factory_.InvalidateWeakPtrs();
654   wait_interval_.reset();
655   NotifyRetryTime(base::Time());
656   poll_timer_.Stop();
657   pending_wakeup_timer_.Stop();
658   pending_configure_params_.reset();
659   if (started_)
660     started_ = false;
661 }
662 
663 // This is the only place where we invoke DoSyncCycleJob with canary
664 // privileges.  Everyone else should use NORMAL_PRIORITY.
TryCanaryJob()665 void SyncSchedulerImpl::TryCanaryJob() {
666   next_sync_cycle_job_priority_ = CANARY_PRIORITY;
667   SDVLOG(2) << "Attempting canary job";
668   TrySyncCycleJob();
669 }
670 
TrySyncCycleJob()671 void SyncSchedulerImpl::TrySyncCycleJob() {
672   // Post call to TrySyncCycleJobImpl on current sequence. Later request for
673   // access token will be here.
674   base::SequencedTaskRunnerHandle::Get()->PostTask(
675       FROM_HERE, base::BindOnce(&SyncSchedulerImpl::TrySyncCycleJobImpl,
676                                 weak_ptr_factory_.GetWeakPtr()));
677 }
678 
TrySyncCycleJobImpl()679 void SyncSchedulerImpl::TrySyncCycleJobImpl() {
680   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
681 
682   // TODO(treib): Pass this as a parameter instead.
683   JobPriority priority = next_sync_cycle_job_priority_;
684   next_sync_cycle_job_priority_ = NORMAL_PRIORITY;
685 
686   nudge_tracker_.SetSyncCycleStartTime(TimeTicks::Now());
687 
688   if (mode_ == CONFIGURATION_MODE) {
689     if (pending_configure_params_) {
690       SDVLOG(2) << "Found pending configure job";
691       DoConfigurationSyncCycleJob(priority);
692     }
693   } else if (CanRunNudgeJobNow(priority)) {
694     if (nudge_tracker_.IsSyncRequired(GetEnabledAndUnblockedTypes())) {
695       SDVLOG(2) << "Found pending nudge job";
696       DoNudgeSyncCycleJob(priority);
697     } else if (((TimeTicks::Now() - last_poll_reset_) >= GetPollInterval())) {
698       SDVLOG(2) << "Found pending poll";
699       DoPollSyncCycleJob();
700     }
701   } else {
702     // We must be in an error state. Transitioning out of each of these
703     // error states should trigger a canary job.
704     DCHECK(IsGlobalThrottle() || IsGlobalBackoff() ||
705            cycle_context_->connection_manager()->HasInvalidAccessToken());
706   }
707 
708   RestartWaiting();
709 }
710 
PollTimerCallback()711 void SyncSchedulerImpl::PollTimerCallback() {
712   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
713   DCHECK(!syncer_->IsSyncing());
714 
715   TrySyncCycleJob();
716 }
717 
RetryTimerCallback()718 void SyncSchedulerImpl::RetryTimerCallback() {
719   TrySyncCycleJob();
720 }
721 
Unthrottle()722 void SyncSchedulerImpl::Unthrottle() {
723   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
724   DCHECK_EQ(WaitInterval::THROTTLED, wait_interval_->mode);
725 
726   // We're no longer throttled, so clear the wait interval.
727   wait_interval_.reset();
728 
729   // We treat this as a 'canary' in the sense that it was originally scheduled
730   // to run some time ago, failed, and we now want to retry, versus a job that
731   // was just created (e.g via ScheduleNudgeImpl). The main implication is
732   // that we're careful to update routing info (etc) with such potentially
733   // stale canary jobs.
734   TryCanaryJob();
735 }
736 
OnTypesUnblocked()737 void SyncSchedulerImpl::OnTypesUnblocked() {
738   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
739 
740   nudge_tracker_.UpdateTypeThrottlingAndBackoffState();
741 
742   // Maybe this is a good time to run a nudge job.  Let's try it.
743   // If not a good time, reschedule a new run.
744   if (nudge_tracker_.IsSyncRequired(GetEnabledAndUnblockedTypes()) &&
745       CanRunNudgeJobNow(NORMAL_PRIORITY)) {
746     TrySyncCycleJob();
747   } else {
748     RestartWaiting();
749   }
750 }
751 
PerformDelayedNudge()752 void SyncSchedulerImpl::PerformDelayedNudge() {
753   // Circumstances may have changed since we scheduled this delayed nudge.
754   // We must check to see if it's OK to run the job before we do so.
755   if (CanRunNudgeJobNow(NORMAL_PRIORITY)) {
756     TrySyncCycleJob();
757   } else {
758     // If we set |wait_interval_| while this PerformDelayedNudge was pending
759     // callback scheduled to |retry_timer_|, it's possible we didn't re-schedule
760     // because this PerformDelayedNudge was going to execute sooner. If that's
761     // the case, we need to make sure we setup to waiting callback now.
762     RestartWaiting();
763   }
764 }
765 
ExponentialBackoffRetry()766 void SyncSchedulerImpl::ExponentialBackoffRetry() {
767   TryCanaryJob();
768 }
769 
NotifyRetryTime(base::Time retry_time)770 void SyncSchedulerImpl::NotifyRetryTime(base::Time retry_time) {
771   for (auto& observer : *cycle_context_->listeners())
772     observer.OnRetryTimeChanged(retry_time);
773 }
774 
NotifyBlockedTypesChanged()775 void SyncSchedulerImpl::NotifyBlockedTypesChanged() {
776   ModelTypeSet types = nudge_tracker_.GetBlockedTypes();
777   ModelTypeSet throttled_types;
778   ModelTypeSet backed_off_types;
779   for (ModelType type : types) {
780     WaitInterval::BlockingMode mode = nudge_tracker_.GetTypeBlockingMode(type);
781     if (mode == WaitInterval::THROTTLED) {
782       throttled_types.Put(type);
783     } else if (mode == WaitInterval::EXPONENTIAL_BACKOFF ||
784                mode == WaitInterval::EXPONENTIAL_BACKOFF_RETRYING) {
785       backed_off_types.Put(type);
786     }
787   }
788 
789   for (auto& observer : *cycle_context_->listeners()) {
790     observer.OnThrottledTypesChanged(IsGlobalThrottle() ? ModelTypeSet::All()
791                                                         : throttled_types);
792     observer.OnBackedOffTypesChanged(IsGlobalBackoff() ? ModelTypeSet::All()
793                                                        : backed_off_types);
794   }
795 }
796 
IsGlobalThrottle() const797 bool SyncSchedulerImpl::IsGlobalThrottle() const {
798   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
799   return wait_interval_ && wait_interval_->mode == WaitInterval::THROTTLED;
800 }
801 
IsGlobalBackoff() const802 bool SyncSchedulerImpl::IsGlobalBackoff() const {
803   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
804   return wait_interval_ &&
805          wait_interval_->mode == WaitInterval::EXPONENTIAL_BACKOFF;
806 }
807 
OnThrottled(const TimeDelta & throttle_duration)808 void SyncSchedulerImpl::OnThrottled(const TimeDelta& throttle_duration) {
809   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
810   wait_interval_ = std::make_unique<WaitInterval>(WaitInterval::THROTTLED,
811                                                   throttle_duration);
812   for (auto& observer : *cycle_context_->listeners()) {
813     observer.OnThrottledTypesChanged(ModelTypeSet::All());
814   }
815   RestartWaiting();
816 }
817 
OnTypesThrottled(ModelTypeSet types,const TimeDelta & throttle_duration)818 void SyncSchedulerImpl::OnTypesThrottled(ModelTypeSet types,
819                                          const TimeDelta& throttle_duration) {
820   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
821   SDVLOG(1) << "Throttling " << ModelTypeSetToString(types) << " for "
822             << throttle_duration.InMinutes() << " minutes.";
823   nudge_tracker_.SetTypesThrottledUntil(types, throttle_duration,
824                                         TimeTicks::Now());
825   RestartWaiting();
826 }
827 
OnTypesBackedOff(ModelTypeSet types)828 void SyncSchedulerImpl::OnTypesBackedOff(ModelTypeSet types) {
829   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
830   for (ModelType type : types) {
831     TimeDelta last_backoff_time =
832         TimeDelta::FromSeconds(kInitialBackoffRetrySeconds);
833     if (nudge_tracker_.GetTypeBlockingMode(type) ==
834         WaitInterval::EXPONENTIAL_BACKOFF_RETRYING) {
835       last_backoff_time = nudge_tracker_.GetTypeLastBackoffInterval(type);
836     }
837 
838     TimeDelta length = delay_provider_->GetDelay(last_backoff_time);
839     nudge_tracker_.SetTypeBackedOff(type, length, TimeTicks::Now());
840     SDVLOG(1) << "Backing off " << ModelTypeToString(type) << " for "
841               << length.InSeconds() << " second.";
842   }
843   RestartWaiting();
844 }
845 
IsAnyThrottleOrBackoff()846 bool SyncSchedulerImpl::IsAnyThrottleOrBackoff() {
847   return wait_interval_ || nudge_tracker_.IsAnyTypeBlocked();
848 }
849 
OnReceivedPollIntervalUpdate(const TimeDelta & new_interval)850 void SyncSchedulerImpl::OnReceivedPollIntervalUpdate(
851     const TimeDelta& new_interval) {
852   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
853 
854   if (new_interval == syncer_poll_interval_seconds_)
855     return;
856   SDVLOG(1) << "Updating poll interval to " << new_interval.InMinutes()
857             << " minutes.";
858   syncer_poll_interval_seconds_ = new_interval;
859   AdjustPolling(UPDATE_INTERVAL);
860 }
861 
OnReceivedCustomNudgeDelays(const std::map<ModelType,TimeDelta> & nudge_delays)862 void SyncSchedulerImpl::OnReceivedCustomNudgeDelays(
863     const std::map<ModelType, TimeDelta>& nudge_delays) {
864   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
865 
866   if (force_short_nudge_delay_for_test_)
867     return;
868 
869   nudge_tracker_.OnReceivedCustomNudgeDelays(nudge_delays);
870 }
871 
OnReceivedClientInvalidationHintBufferSize(int size)872 void SyncSchedulerImpl::OnReceivedClientInvalidationHintBufferSize(int size) {
873   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
874 
875   if (size > 0)
876     nudge_tracker_.SetHintBufferSize(size);
877   else
878     NOTREACHED() << "Hint buffer size should be > 0.";
879 }
880 
OnSyncProtocolError(const SyncProtocolError & sync_protocol_error)881 void SyncSchedulerImpl::OnSyncProtocolError(
882     const SyncProtocolError& sync_protocol_error) {
883   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
884 
885   if (ShouldRequestEarlyExit(sync_protocol_error)) {
886     SDVLOG(2) << "Sync Scheduler requesting early exit.";
887     Stop();
888   }
889   if (IsActionableError(sync_protocol_error)) {
890     SDVLOG(2) << "OnActionableError";
891     for (auto& observer : *cycle_context_->listeners())
892       observer.OnActionableError(sync_protocol_error);
893   }
894 }
895 
OnReceivedGuRetryDelay(const TimeDelta & delay)896 void SyncSchedulerImpl::OnReceivedGuRetryDelay(const TimeDelta& delay) {
897   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
898 
899   nudge_tracker_.SetNextRetryTime(TimeTicks::Now() + delay);
900   retry_timer_.Start(FROM_HERE, delay, this,
901                      &SyncSchedulerImpl::RetryTimerCallback);
902 }
903 
OnReceivedMigrationRequest(ModelTypeSet types)904 void SyncSchedulerImpl::OnReceivedMigrationRequest(ModelTypeSet types) {
905   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
906 
907   for (auto& observer : *cycle_context_->listeners())
908     observer.OnMigrationRequested(types);
909 }
910 
SetNotificationsEnabled(bool notifications_enabled)911 void SyncSchedulerImpl::SetNotificationsEnabled(bool notifications_enabled) {
912   DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);
913 
914   cycle_context_->set_notifications_enabled(notifications_enabled);
915   if (notifications_enabled)
916     nudge_tracker_.OnInvalidationsEnabled();
917   else
918     nudge_tracker_.OnInvalidationsDisabled();
919 }
920 
IsEarlierThanCurrentPendingJob(const TimeDelta & delay)921 bool SyncSchedulerImpl::IsEarlierThanCurrentPendingJob(const TimeDelta& delay) {
922   TimeTicks incoming_run_time = TimeTicks::Now() + delay;
923   if (pending_wakeup_timer_.IsRunning() &&
924       (pending_wakeup_timer_.desired_run_time() < incoming_run_time)) {
925     // Old job arrives sooner than this one.
926     return false;
927   }
928   return true;
929 }
930 
931 #undef SDVLOG_LOC
932 #undef SDVLOG
933 #undef ENUM_CASE
934 
935 }  // namespace syncer
936