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

sync/engine/sync_scheduler_impl.cc

 // Copyright (c) 2012 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "sync/engine/sync_scheduler_impl.h"
 
 #include <algorithm>
 #include <cstring>
 
+#include "base/auto_reset.h"
 #include "base/bind.h"
 #include "base/compiler_specific.h"
 #include "base/location.h"
 #include "base/logging.h"
 #include "base/message_loop.h"
 #include "sync/engine/backoff_delay_provider.h"
 #include "sync/engine/syncer.h"
 #include "sync/engine/throttled_data_type_tracker.h"
 #include "sync/protocol/proto_enum_conversions.h"
 #include "sync/protocol/sync.pb.h"
@@ skipping 179 matching lines @@
       syncer_long_poll_interval_seconds_(
           TimeDelta::FromSeconds(kDefaultLongPollIntervalSeconds)),
       sessions_commit_delay_(
           TimeDelta::FromSeconds(kDefaultSessionsCommitDelaySeconds)),
       mode_(NORMAL_MODE),
       // Start with assuming everything is fine with the connection.
       // At the end of the sync cycle we would have the correct status.
       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_);
 }
 
 SyncSchedulerImpl::~SyncSchedulerImpl() {
   DCHECK_EQ(MessageLoop::current(), sync_loop_);
   StopImpl(base::Closure());
 }
 
 void SyncSchedulerImpl::OnCredentialsUpdated() {
   DCHECK_EQ(MessageLoop::current(), sync_loop_);
@@ skipping 48 matching lines @@
 
   DCHECK(!session_context_->account_name().empty());
   DCHECK(syncer_.get());
   Mode old_mode = mode_;
   mode_ = mode;
   AdjustPolling(NULL);  // Will kick start poll timer if needed.
 
   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);
   }
 }
 
 void SyncSchedulerImpl::SendInitialSnapshot() {
   DCHECK_EQ(MessageLoop::current(), sync_loop_);
   scoped_ptr<SyncSession> dummy(new SyncSession(session_context_, this,
       SyncSourceInfo(), ModelSafeRoutingInfo(),
       std::vector<ModelSafeWorker*>()));
   SyncEngineEvent event(SyncEngineEvent::STATUS_CHANGED);
@@ skipping 155 matching lines @@
     else if (job.purpose == SyncSessionJob::CONFIGURATION)
       return CONTINUE;
     else
       return DROP;
   }
 
   // We are in normal mode.
   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;
 
   SDVLOG(2) << "No valid auth token. Using that to decide on job.";
   return job.purpose == SyncSessionJob::NUDGE ? SAVE : DROP;
 }
 
 void SyncSchedulerImpl::InitOrCoalescePendingJob(const SyncSessionJob& job) {
   DCHECK_EQ(MessageLoop::current(), sync_loop_);
   DCHECK(job.purpose != SyncSessionJob::CONFIGURATION);
   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()));
 
     SyncSessionJob new_job(SyncSessionJob::NUDGE, job.scheduled_start,
         make_linked_ptr(session.release()), false,
         ConfigurationParams(), job.from_here);
     pending_nudge_.reset(new SyncSessionJob(new_job));
-
     return;
   }
 
   SDVLOG(2) << "Coalescing a pending nudge";
   pending_nudge_->session->Coalesce(*(job.session.get()));
   pending_nudge_->scheduled_start = job.scheduled_start;
 
   // Unfortunately the nudge location cannot be modified. So it stores the
   // location of the first caller.
 }
@@ skipping 90 matching lines @@
                                        false,
                                        nudge_location);
 }
 
 void SyncSchedulerImpl::ScheduleNudgeImpl(
     const TimeDelta& delay,
     GetUpdatesCallerInfo::GetUpdatesSource source,
     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 "
       << delay.InMilliseconds() << " ms, "
       << "source " << GetUpdatesSourceString(source) << ", "
       << "payloads "
       << ModelTypeStateMapToString(type_state_map)
       << (is_canary_job ? " (canary)" : "");
 
   SyncSourceInfo info(source, type_state_map);
+  UpdateNudgeTimeRecords(info);
 
   SyncSession* session(CreateSyncSession(info));
   SyncSessionJob job(SyncSessionJob::NUDGE, TimeTicks::Now() + delay,
                      make_linked_ptr(session), is_canary_job,
                      ConfigurationParams(), nudge_location);
 
   session = NULL;
   if (!ShouldRunJob(job))
     return;
 
@@ skipping 83 matching lines @@
   DCHECK_EQ(MessageLoop::current(), sync_loop_);
   if (!started_) {
     SDVLOG(1) << "Not posting task as scheduler is stopped.";
     return;
   }
   sync_loop_->PostDelayedTask(from_here, task, delay);
 }
 
 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);
   SDVLOG_LOC(job.from_here, 2)
       << "In ScheduleSyncSessionJob with "
       << SyncSessionJob::GetPurposeString(job.purpose)
       << " job and " << delay.InMilliseconds() << " ms delay";
 
   DCHECK(job.purpose == SyncSessionJob::NUDGE ||
          job.purpose == SyncSessionJob::POLL);
   if (job.purpose == SyncSessionJob::NUDGE) {
     SDVLOG_LOC(job.from_here, 2) << "Resetting pending_nudge";
     DCHECK(!pending_nudge_.get() || pending_nudge_->session.get() ==
            job.session);
     pending_nudge_.reset(new SyncSessionJob(job));
   }
   PostDelayedTask(job.from_here, "DoSyncSessionJob",
                   base::Bind(&SyncSchedulerImpl::DoSyncSessionJob,
                              weak_ptr_factory_.GetWeakPtr(),
                              job),
                   delay);
 }
 
 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 "
         << SyncSessionJob::GetPurposeString(job.purpose) << " job from "
         << GetUpdatesSourceString(job.session->source().updates_source);
     return;
   }
 
   if (job.purpose == SyncSessionJob::NUDGE) {
     if (pending_nudge_.get() == NULL ||
@@ skipping 24 matching lines @@
     syncer_->SyncShare(job.session.get(), begin, end);
     has_more_to_sync = job.session->HasMoreToSync();
     if (has_more_to_sync)
       job.session->PrepareForAnotherSyncCycle();
   }
   SDVLOG(2) << "Done SyncShare looping.";
 
   FinishSyncSessionJob(job);
 }
 
+void SyncSchedulerImpl::UpdateNudgeTimeRecords(const SyncSourceInfo& info) {
+  DCHECK_EQ(MessageLoop::current(), sync_loop_);
+
+  // We are interested in recording time between local nudges for datatypes.
+  // TODO(tim): Consider tracking LOCAL_NOTIFICATION as well.
+  if (info.updates_source != GetUpdatesCallerInfo::LOCAL)
+    return;
+
+  base::TimeTicks now = TimeTicks::Now();
+  // Update timing information for how often datatypes are triggering nudges.
+  for (ModelTypeStateMap::const_iterator iter = info.types.begin();
+       iter != info.types.end();
+       ++iter) {
+    base::TimeTicks previous = last_local_nudges_by_model_type_[iter->first];
+    last_local_nudges_by_model_type_[iter->first] = now;
+    if (previous.is_null())
+      continue;
+
+#define PER_DATA_TYPE_MACRO(type_str) \
+    SYNC_FREQ_HISTOGRAM("Sync.Freq" type_str, now - previous);
+      SYNC_DATA_TYPE_HISTOGRAM(iter->first);
+#undef PER_DATA_TYPE_MACRO
+  }
+}
+
 void SyncSchedulerImpl::FinishSyncSessionJob(const SyncSessionJob& job) {
   DCHECK_EQ(MessageLoop::current(), sync_loop_);
-  // Update timing information for how often datatypes are triggering nudges.
-  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) {
-#define PER_DATA_TYPE_MACRO(type_str) \
-    SYNC_FREQ_HISTOGRAM("Sync.Freq" type_str, \
-                        now - last_sync_session_end_time_);
-      SYNC_DATA_TYPE_HISTOGRAM(iter->first);
-#undef PER_DATA_TYPE_MACRO
-    }
-  }
-  last_sync_session_end_time_ = now;
-
   // 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.
   //
   // TODO(rlarocque): crbug.com/110954
   // We should get rid of the notifications and it is probably not needed to
   // maintain this status variable in 2 places. We should query it directly from
   // SCM when needed.
   ServerConnectionManager* scm = session_context_->connection_manager();
   UpdateServerConnectionManagerStatus(scm->server_status());
 
   if (IsSyncingCurrentlySilenced()) {
     SDVLOG(2) << "We are currently throttled; not scheduling the next sync.";
     // TODO(sync): Investigate whether we need to check job.purpose
     // here; see DCHECKs in SaveJob().  (See http://crbug.com/90868.)
     SaveJob(job);
     return;  // Nothing to do.
   } else if (job.session->Succeeded() &&
              !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();
   }
 
   SDVLOG(2) << "Updating the next polling time after SyncMain";
   ScheduleNextSync(job);
 }
 
 void SyncSchedulerImpl::ScheduleNextSync(const SyncSessionJob& old_job) {
   DCHECK_EQ(MessageLoop::current(), sync_loop_);
   DCHECK(!old_job.session->HasMoreToSync());
@@ skipping 146 matching lines @@
 
 void SyncSchedulerImpl::DoPendingJobIfPossible(bool is_canary_job) {
   DCHECK_EQ(MessageLoop::current(), sync_loop_);
   SyncSessionJob* job_to_execute = NULL;
   if (mode_ == CONFIGURATION_MODE && wait_interval_.get()
       && wait_interval_->pending_configure_job.get()) {
     SDVLOG(2) << "Found pending configure 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()));
 
     // Also the routing info might have been changed since we cached the
     // pending nudge. Update it by coalescing to the latest.
     pending_nudge_->session->Coalesce(*(session.get()));
     // The pending nudge would be cleared in the DoSyncSessionJob function.
     job_to_execute = pending_nudge_.get();
   }
@@ skipping 128 matching lines @@
 
 #undef SDVLOG_LOC
 
 #undef SDVLOG
 
 #undef SLOG
 
 #undef ENUM_CASE
 
 }  // namespace syncer