sync: remove buggy freshness condition in SyncSchedulerImpl add defensive DCHECKs.

sync/engine/sync_scheduler_impl.cc

Index: sync/engine/sync_scheduler_impl.cc
diff --git a/sync/engine/sync_scheduler_impl.cc b/sync/engine/sync_scheduler_impl.cc
index 195eda41358592f11d3ee9ad7e9c839cbd3fa598..f3916fb88cacdcdcf7b42248ab86615fd0cf06f2 100644
--- a/sync/engine/sync_scheduler_impl.cc
+++ b/sync/engine/sync_scheduler_impl.cc
@@ -7,6 +7,7 @@
 #include <algorithm>
 #include <cstring>
 
+#include "base/auto_reset.h"
 #include "base/bind.h"
 #include "base/compiler_specific.h"
 #include "base/location.h"
@@ -206,7 +207,8 @@ SyncSchedulerImpl::SyncSchedulerImpl(const std::string& name,
       connection_code_(HttpResponse::SERVER_CONNECTION_OK),
       delay_provider_(delay_provider),
       syncer_(syncer),
-      session_context_(context) {
+      session_context_(context),
+      no_scheduling_allowed_(false) {
   DCHECK(sync_loop_);
 }
 
@@ -275,6 +277,13 @@ void SyncSchedulerImpl::Start(Mode mode) {
   if (old_mode != mode_) {
     // We just changed our mode. See if there are any pending jobs that we could
     // execute in the new mode.
+    if (mode_ == NORMAL_MODE) {
+      // It is illegal to switch to NORMAL_MODE if a previous CONFIGURATION job
+      // has not yet completed.
+      DCHECK(!wait_interval_.get() ||
+             !wait_interval_->pending_configure_job.get());
+    }
+
     DoPendingJobIfPossible(false);
   }
 }
@@ -450,12 +459,43 @@ SyncSchedulerImpl::JobProcessDecision SyncSchedulerImpl::DecideOnJob(
   DCHECK_EQ(mode_, NORMAL_MODE);
   DCHECK_NE(job.purpose, SyncSessionJob::CONFIGURATION);
 
-  // Freshness condition
-  if (job.scheduled_start < last_sync_session_end_time_) {
-    SDVLOG(2) << "Dropping job because of freshness";
-    return DROP;
-  }
+  // Note about some subtle scheduling semantics.
+  //
+  // It's possible at this point that |job| is known to be unnecessary, and
+  // dropping it would be perfectly safe and correct. Consider
+  //
+  // 1) |job| is a POLL with a |scheduled_start| time that is less than
+  //    the time that the last successful all-datatype NUDGE completed.
+  //
+  // 2) |job| is a NUDGE (for any combination of types) with a
+  //    |scheduled_start| time that is less than the time that the last
+  //    successful all-datatype NUDGE completed, and it has a NOTIFICATION
+  //    GetUpdatesCallerInfo value yet offers no new notification hint.
+  //
+  // 3) |job| is a NUDGE with a |scheduled_start| time that is less than
+  //    the time that the last successful matching-datatype NUDGE completed,
+  //    and payloads (hints) are identical to that last successful NUDGE.
+  //
+  //  Case 1 can occur if the POLL timer fires *after* a call to
+  //  ScheduleSyncSessionJob for a NUDGE, but *before* the thread actually
+  //  picks the resulting posted task off of the MessageLoop. The NUDGE will
+  //  run first and complete at a time greater than the POLL scheduled_start.
+  //  However, this case (and POLLs in general) is so rare that we ignore it (
+  //  and avoid the required bookeeping to simplify code).
+  //
+  //  We avoid cases 2 and 3 by externally synchronizing NUDGE requests --
+  //  scheduling a NUDGE requires command of the sync thread, which is
+  //  impossible* from outside of SyncScheduler if a NUDGE is taking place.
+  //  And if you have command of the sync thread when scheduling a NUDGE and a
+  //  previous NUDGE exists, they will be coalesced and the stale job will be
+  //  cancelled via the session-equality check in DoSyncSessionJob.
+  //
+  //  * It's not strictly "impossible", but it would be reentrant and hence
+  //  illegal. e.g. scheduling a job and re-entering the SyncScheduler is NOT a
+  //  legal side effect of any of the work being done as part of a sync cycle.
+  //  See |no_scheduling_allowed_| for details.
 
+  // Decision now rests on state of auth tokens.
   if (!session_context_->connection_manager()->HasInvalidAuthToken())
     return CONTINUE;
 
@@ -469,6 +509,9 @@ void SyncSchedulerImpl::InitOrCoalescePendingJob(const SyncSessionJob& job) {
   if (pending_nudge_.get() == NULL) {
     SDVLOG(2) << "Creating a pending nudge job";
     SyncSession* s = job.session.get();
+
+    // Get a fresh session with similar configuration as before (resets
+    // StatusController).
     scoped_ptr<SyncSession> session(new SyncSession(s->context(),
         s->delegate(), s->source(), s->routing_info(), s->workers()));
 
@@ -476,7 +519,6 @@ void SyncSchedulerImpl::InitOrCoalescePendingJob(const SyncSessionJob& job) {
         make_linked_ptr(session.release()), false,
         ConfigurationParams(), job.from_here);
     pending_nudge_.reset(new SyncSessionJob(new_job));
-
     return;
   }
 
@@ -587,6 +629,7 @@ void SyncSchedulerImpl::ScheduleNudgeImpl(
     const ModelTypeStateMap& type_state_map,
     bool is_canary_job, const tracked_objects::Location& nudge_location) {
   DCHECK_EQ(MessageLoop::current(), sync_loop_);
+  DCHECK(!type_state_map.empty()) << "Nudge scheduled for no types!";
 
   SDVLOG_LOC(nudge_location, 2)
       << "In ScheduleNudgeImpl with delay "
@@ -597,6 +640,7 @@ void SyncSchedulerImpl::ScheduleNudgeImpl(
       << (is_canary_job ? " (canary)" : "");
 
   SyncSourceInfo info(source, type_state_map);
+  UpdateNudgeTimeRecords(info);
 
   SyncSession* session(CreateSyncSession(info));
   SyncSessionJob job(SyncSessionJob::NUDGE, TimeTicks::Now() + delay,
@@ -700,6 +744,11 @@ void SyncSchedulerImpl::PostDelayedTask(
 
 void SyncSchedulerImpl::ScheduleSyncSessionJob(const SyncSessionJob& job) {
   DCHECK_EQ(MessageLoop::current(), sync_loop_);
+  if (no_scheduling_allowed_) {
+    NOTREACHED() << "Illegal to schedule job while session in progress.";
+    return;
+  }
+
   TimeDelta delay = job.scheduled_start - TimeTicks::Now();
   if (delay < TimeDelta::FromMilliseconds(0))
     delay = TimeDelta::FromMilliseconds(0);
@@ -725,6 +774,8 @@ void SyncSchedulerImpl::ScheduleSyncSessionJob(const SyncSessionJob& job) {
 
 void SyncSchedulerImpl::DoSyncSessionJob(const SyncSessionJob& job) {
   DCHECK_EQ(MessageLoop::current(), sync_loop_);
+
+  AutoReset<bool> protector(&no_scheduling_allowed_, true);
   if (!ShouldRunJob(job)) {
     SLOG(WARNING)
         << "Not executing "
@@ -769,24 +820,35 @@ void SyncSchedulerImpl::DoSyncSessionJob(const SyncSessionJob& job) {
   FinishSyncSessionJob(job);
 }
 
-void SyncSchedulerImpl::FinishSyncSessionJob(const SyncSessionJob& job) {
+void SyncSchedulerImpl::UpdateNudgeTimeRecords(const SyncSourceInfo& info) {
   DCHECK_EQ(MessageLoop::current(), sync_loop_);
-  // Update timing information for how often datatypes are triggering nudges.
+
+  // We are interested in recording time between local nudges for datatypes.

[Nicolas Zea, 2012/09/06 22:40:57]

maybe add a TODO: consider recording LOCAL_NOTIFICATION types as well?

[tim (not reviewing), 2012/09/06 23:12:52]

Done.

+  if (info.updates_source != GetUpdatesCallerInfo::LOCAL)
+    return;
+
   base::TimeTicks now = TimeTicks::Now();
-  if (!last_sync_session_end_time_.is_null()) {
-    ModelTypeStateMap::const_iterator iter;
-    for (iter = job.session->source().types.begin();
-         iter != job.session->source().types.end();
-         ++iter) {
+  // Update timing information for how often datatypes are triggering nudges.
+  if (!last_local_nudges_by_model_type_.empty()) {
+    ModelTypeStateMap::const_iterator iter = info.types.begin();

[Nicolas Zea, 2012/09/06 22:40:57]

nit: move this into for loop declaration?

[tim (not reviewing), 2012/09/06 23:12:52]

Done.

+    for (; iter != info.types.end(); ++iter) {
+      if (last_local_nudges_by_model_type_.find(iter->first) ==
+          last_local_nudges_by_model_type_.end()) {
+        continue;

[Nicolas Zea, 2012/09/06 22:40:57]

shouldn't this insert now into the map for the type before continuing?

[tim (not reviewing), 2012/09/06 23:12:52]

Gah. Yeah.  Re-worked this.

+      }
+
 #define PER_DATA_TYPE_MACRO(type_str) \
     SYNC_FREQ_HISTOGRAM("Sync.Freq" type_str, \
-                        now - last_sync_session_end_time_);
+                        now - last_local_nudges_by_model_type_[iter->first]);

[Nicolas Zea, 2012/09/06 22:40:57]

nit: save the iterator from the find(..) above and reuse it here.

[tim (not reviewing), 2012/09/06 23:12:52]

See new code.

       SYNC_DATA_TYPE_HISTOGRAM(iter->first);
 #undef PER_DATA_TYPE_MACRO
+      last_local_nudges_by_model_type_[iter->first] = now;
     }
   }
-  last_sync_session_end_time_ = now;
+}
 
+void SyncSchedulerImpl::FinishSyncSessionJob(const SyncSessionJob& job) {
+  DCHECK_EQ(MessageLoop::current(), sync_loop_);
   // Now update the status of the connection from SCM. We need this to decide
   // whether we need to save/run future jobs. The notifications from SCM are not
   // reliable.
@@ -808,6 +870,7 @@ void SyncSchedulerImpl::FinishSyncSessionJob(const SyncSessionJob& job) {
              !job.config_params.ready_task.is_null()) {
     // If this was a configuration job with a ready task, invoke it now that
     // we finished successfully.
+    AutoReset<bool> protector(&no_scheduling_allowed_, true);
     job.config_params.ready_task.Run();
   }
 
@@ -974,10 +1037,6 @@ void SyncSchedulerImpl::DoPendingJobIfPossible(bool is_canary_job) {
     job_to_execute = wait_interval_->pending_configure_job.get();
   } else if (mode_ == NORMAL_MODE && pending_nudge_.get()) {
     SDVLOG(2) << "Found pending nudge job";
-    // Pending jobs mostly have time from the past. Reset it so this job
-    // will get executed.
-    if (pending_nudge_->scheduled_start < TimeTicks::Now())
-      pending_nudge_->scheduled_start = TimeTicks::Now();
 
     scoped_ptr<SyncSession> session(CreateSyncSession(
         pending_nudge_->session->source()));