1// Copyright 2014 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 "chrome/browser/sync/startup_controller.h"
6
7#include "base/command_line.h"
8#include "base/message_loop/message_loop.h"
9#include "base/metrics/histogram.h"
10#include "base/strings/string_number_conversions.h"
11#include "chrome/browser/sync/supervised_user_signin_manager_wrapper.h"
12#include "chrome/common/chrome_switches.h"
13#include "components/signin/core/browser/profile_oauth2_token_service.h"
14#include "components/sync_driver/sync_prefs.h"
15
16namespace browser_sync {
17
18namespace {
19
20// The amount of time we'll wait to initialize sync if no data type triggers
21// initialization via a StartSyncFlare.
22const int kDeferredInitFallbackSeconds = 10;
23
24// Enum (for UMA, primarily) defining different events that cause us to
25// exit the "deferred" state of initialization and invoke start_backend.
26enum DeferredInitTrigger {
27  // We have received a signal from a SyncableService requesting that sync
28  // starts as soon as possible.
29  TRIGGER_DATA_TYPE_REQUEST,
30  // No data type requested sync to start and our fallback timer expired.
31  TRIGGER_FALLBACK_TIMER,
32  MAX_TRIGGER_VALUE
33};
34
35}  // namespace
36
37StartupController::StartupController(
38    ProfileSyncServiceStartBehavior start_behavior,
39    const ProfileOAuth2TokenService* token_service,
40    const sync_driver::SyncPrefs* sync_prefs,
41    const SupervisedUserSigninManagerWrapper* signin,
42    base::Closure start_backend)
43    : received_start_request_(false),
44      setup_in_progress_(false),
45      auto_start_enabled_(start_behavior == AUTO_START),
46      sync_prefs_(sync_prefs),
47      token_service_(token_service),
48      signin_(signin),
49      start_backend_(start_backend),
50      fallback_timeout_(
51          base::TimeDelta::FromSeconds(kDeferredInitFallbackSeconds)),
52      first_start_(true),
53      weak_factory_(this) {
54
55  if (CommandLine::ForCurrentProcess()->HasSwitch(
56          switches::kSyncDeferredStartupTimeoutSeconds)) {
57    int timeout = kDeferredInitFallbackSeconds;
58    if (base::StringToInt(CommandLine::ForCurrentProcess()->GetSwitchValueASCII(
59            switches::kSyncDeferredStartupTimeoutSeconds), &timeout)) {
60      DCHECK_GE(timeout, 0);
61      DVLOG(2) << "Sync StartupController overriding startup timeout to "
62               << timeout << " seconds.";
63      fallback_timeout_ = base::TimeDelta::FromSeconds(timeout);
64    }
65  }
66}
67
68StartupController::~StartupController() {}
69
70void StartupController::Reset(const syncer::ModelTypeSet registered_types) {
71  received_start_request_ = false;
72  start_up_time_ = base::Time();
73  start_backend_time_ = base::Time();
74  // Don't let previous timers affect us post-reset.
75  weak_factory_.InvalidateWeakPtrs();
76  registered_types_ = registered_types;
77}
78
79void StartupController::set_setup_in_progress(bool in_progress) {
80  setup_in_progress_ = in_progress;
81}
82
83bool StartupController::StartUp(StartUpDeferredOption deferred_option) {
84  const bool first_start = start_up_time_.is_null();
85  if (first_start)
86    start_up_time_ = base::Time::Now();
87
88  if (deferred_option == STARTUP_BACKEND_DEFERRED &&
89      !CommandLine::ForCurrentProcess()->HasSwitch(
90          switches::kSyncDisableDeferredStartup) &&
91      sync_prefs_->GetPreferredDataTypes(registered_types_)
92          .Has(syncer::SESSIONS)) {
93    if (first_start) {
94      base::MessageLoop::current()->PostDelayedTask(
95          FROM_HERE,
96          base::Bind(&StartupController::OnFallbackStartupTimerExpired,
97                     weak_factory_.GetWeakPtr()), fallback_timeout_);
98    }
99    return false;
100  }
101
102  if (start_backend_time_.is_null()) {
103    start_backend_time_ = base::Time::Now();
104    start_backend_.Run();
105    first_start_ = false;
106  }
107
108  return true;
109}
110
111void StartupController::OverrideFallbackTimeoutForTest(
112    const base::TimeDelta& timeout) {
113  fallback_timeout_ = timeout;
114}
115
116bool StartupController::TryStart() {
117  if (sync_prefs_->IsManaged())
118    return false;
119
120  if (sync_prefs_->IsStartSuppressed())
121    return false;
122
123  if (signin_->GetEffectiveUsername().empty())
124    return false;
125
126  if (!token_service_)
127    return false;
128
129  if (!token_service_->RefreshTokenIsAvailable(
130          signin_->GetAccountIdToUse())) {
131    return false;
132  }
133
134  // TODO(tim): Seems wrong to always record this histogram here...
135  // If we got here then tokens are loaded and user logged in and sync is
136  // enabled. If OAuth refresh token is not available then something is wrong.
137  // When PSS requests access token, OAuth2TokenService will return error and
138  // PSS will show error to user asking to reauthenticate.
139  UMA_HISTOGRAM_BOOLEAN("Sync.RefreshTokenAvailable", true);
140
141  // If sync setup has completed we always start the backend. If the user is in
142  // the process of setting up now, we should start the backend to download
143  // account control state / encryption information). If autostart is enabled,
144  // but we haven't completed sync setup, we try to start sync anyway, since
145  // it's possible we crashed/shutdown after logging in but before the backend
146  // finished initializing the last time.
147  //
148  // However, the only time we actually need to start sync _immediately_ is if
149  // we haven't completed sync setup and the user is in the process of setting
150  // up - either they just signed in (for the first time) on an auto-start
151  // platform or they explicitly kicked off sync setup, and e.g we need to
152  // fetch account details like encryption state to populate UI. Otherwise,
153  // for performance reasons and maximizing parallelism at chrome startup, we
154  // defer the heavy lifting for sync init until things have calmed down.
155  if (sync_prefs_->HasSyncSetupCompleted()) {
156    // For first time, defer start if data type hasn't requested sync to avoid
157    // stressing browser start. If |first_start_| is false, most likely the
158    // first attempt to start is intercepted by backup. When backup finishes,
159    // TryStart() is called again and we should start immediately to avoid
160    // unnecessary delay.
161    if (!received_start_request_ && first_start_)
162      return StartUp(STARTUP_BACKEND_DEFERRED);
163    else
164      return StartUp(STARTUP_IMMEDIATE);
165  } else if (setup_in_progress_ || auto_start_enabled_) {
166    // We haven't completed sync setup. Start immediately if the user explicitly
167    // kicked this off or we're supposed to automatically start syncing.
168    return StartUp(STARTUP_IMMEDIATE);
169  }
170
171  return false;
172}
173
174void StartupController::RecordTimeDeferred() {
175  DCHECK(!start_up_time_.is_null());
176  base::TimeDelta time_deferred = base::Time::Now() - start_up_time_;
177  UMA_HISTOGRAM_CUSTOM_TIMES("Sync.Startup.TimeDeferred2",
178      time_deferred,
179      base::TimeDelta::FromSeconds(0),
180      base::TimeDelta::FromMinutes(2),
181      60);
182}
183
184void StartupController::OnFallbackStartupTimerExpired() {
185  DCHECK(!CommandLine::ForCurrentProcess()->HasSwitch(
186      switches::kSyncDisableDeferredStartup));
187
188  if (!start_backend_time_.is_null())
189    return;
190
191  DVLOG(2) << "Sync deferred init fallback timer expired, starting backend.";
192  RecordTimeDeferred();
193  UMA_HISTOGRAM_ENUMERATION("Sync.Startup.DeferredInitTrigger",
194                            TRIGGER_FALLBACK_TIMER,
195                            MAX_TRIGGER_VALUE);
196  received_start_request_ = true;
197  TryStart();
198}
199
200std::string StartupController::GetBackendInitializationStateString() const {
201  if (!start_backend_time_.is_null())
202    return "Started";
203  else if (!start_up_time_.is_null())
204    return "Deferred";
205  else
206    return "Not started";
207}
208
209void StartupController::OnDataTypeRequestsSyncStartup(syncer::ModelType type) {
210  if (CommandLine::ForCurrentProcess()->HasSwitch(
211          switches::kSyncDisableDeferredStartup)) {
212    DVLOG(2) << "Ignoring data type request for sync startup: "
213             << syncer::ModelTypeToString(type);
214    return;
215  }
216
217  if (!start_backend_time_.is_null())
218    return;
219
220  DVLOG(2) << "Data type requesting sync startup: "
221           << syncer::ModelTypeToString(type);
222  // Measure the time spent waiting for init and the type that triggered it.
223  // We could measure the time spent deferred on a per-datatype basis, but
224  // for now this is probably sufficient.
225  if (!start_up_time_.is_null()) {
226    RecordTimeDeferred();
227    UMA_HISTOGRAM_ENUMERATION("Sync.Startup.TypeTriggeringInit",
228                              ModelTypeToHistogramInt(type),
229                              syncer::MODEL_TYPE_COUNT);
230    UMA_HISTOGRAM_ENUMERATION("Sync.Startup.DeferredInitTrigger",
231                              TRIGGER_DATA_TYPE_REQUEST,
232                              MAX_TRIGGER_VALUE);
233  }
234  received_start_request_ = true;
235  TryStart();
236}
237
238}  // namespace browser_sync
239