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/managed_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 ManagedUserSigninManagerWrapper* 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      weak_factory_(this) {
53
54  if (CommandLine::ForCurrentProcess()->HasSwitch(
55          switches::kSyncDeferredStartupTimeoutSeconds)) {
56    int timeout = kDeferredInitFallbackSeconds;
57    if (base::StringToInt(CommandLine::ForCurrentProcess()->GetSwitchValueASCII(
58            switches::kSyncDeferredStartupTimeoutSeconds), &timeout)) {
59      DCHECK_GE(timeout, 0);
60      DVLOG(2) << "Sync StartupController overriding startup timeout to "
61               << timeout << " seconds.";
62      fallback_timeout_ = base::TimeDelta::FromSeconds(timeout);
63    }
64  }
65}
66
67StartupController::~StartupController() {}
68
69void StartupController::Reset(const syncer::ModelTypeSet registered_types) {
70  received_start_request_ = false;
71  start_up_time_ = base::Time();
72  start_backend_time_ = base::Time();
73  // Don't let previous timers affect us post-reset.
74  weak_factory_.InvalidateWeakPtrs();
75  registered_types_ = registered_types;
76}
77
78void StartupController::set_setup_in_progress(bool in_progress) {
79  setup_in_progress_ = in_progress;
80}
81
82bool StartupController::StartUp(StartUpDeferredOption deferred_option) {
83  const bool first_start = start_up_time_.is_null();
84  if (first_start)
85    start_up_time_ = base::Time::Now();
86
87  if (deferred_option == STARTUP_BACKEND_DEFERRED &&
88      !CommandLine::ForCurrentProcess()->HasSwitch(
89          switches::kSyncDisableDeferredStartup) &&
90      sync_prefs_->GetPreferredDataTypes(registered_types_)
91          .Has(syncer::SESSIONS)) {
92    if (first_start) {
93      base::MessageLoop::current()->PostDelayedTask(
94          FROM_HERE,
95          base::Bind(&StartupController::OnFallbackStartupTimerExpired,
96                     weak_factory_.GetWeakPtr()), fallback_timeout_);
97    }
98    return false;
99  }
100
101  if (start_backend_time_.is_null()) {
102    start_backend_time_ = base::Time::Now();
103    start_backend_.Run();
104  }
105
106  return true;
107}
108
109void StartupController::OverrideFallbackTimeoutForTest(
110    const base::TimeDelta& timeout) {
111  fallback_timeout_ = timeout;
112}
113
114bool StartupController::TryStart() {
115  if (sync_prefs_->IsManaged())
116    return false;
117
118  if (sync_prefs_->IsStartSuppressed())
119    return false;
120
121  if (signin_->GetEffectiveUsername().empty())
122    return false;
123
124  if (!token_service_)
125    return false;
126
127  if (!token_service_->RefreshTokenIsAvailable(
128          signin_->GetAccountIdToUse())) {
129    return false;
130  }
131
132  // TODO(tim): Seems wrong to always record this histogram here...
133  // If we got here then tokens are loaded and user logged in and sync is
134  // enabled. If OAuth refresh token is not available then something is wrong.
135  // When PSS requests access token, OAuth2TokenService will return error and
136  // PSS will show error to user asking to reauthenticate.
137  UMA_HISTOGRAM_BOOLEAN("Sync.RefreshTokenAvailable", true);
138
139  // If sync setup has completed we always start the backend. If the user is in
140  // the process of setting up now, we should start the backend to download
141  // account control state / encryption information). If autostart is enabled,
142  // but we haven't completed sync setup, we try to start sync anyway, since
143  // it's possible we crashed/shutdown after logging in but before the backend
144  // finished initializing the last time.
145  //
146  // However, the only time we actually need to start sync _immediately_ is if
147  // we haven't completed sync setup and the user is in the process of setting
148  // up - either they just signed in (for the first time) on an auto-start
149  // platform or they explicitly kicked off sync setup, and e.g we need to
150  // fetch account details like encryption state to populate UI. Otherwise,
151  // for performance reasons and maximizing parallelism at chrome startup, we
152  // defer the heavy lifting for sync init until things have calmed down.
153  if (sync_prefs_->HasSyncSetupCompleted()) {
154    if (!received_start_request_)
155      return StartUp(STARTUP_BACKEND_DEFERRED);
156    else
157      return StartUp(STARTUP_IMMEDIATE);
158  } else if (setup_in_progress_ || auto_start_enabled_) {
159    // We haven't completed sync setup. Start immediately if the user explicitly
160    // kicked this off or we're supposed to automatically start syncing.
161    return StartUp(STARTUP_IMMEDIATE);
162  }
163
164  return false;
165}
166
167void StartupController::RecordTimeDeferred() {
168  DCHECK(!start_up_time_.is_null());
169  base::TimeDelta time_deferred = base::Time::Now() - start_up_time_;
170  UMA_HISTOGRAM_CUSTOM_TIMES("Sync.Startup.TimeDeferred2",
171      time_deferred,
172      base::TimeDelta::FromSeconds(0),
173      base::TimeDelta::FromMinutes(2),
174      60);
175}
176
177void StartupController::OnFallbackStartupTimerExpired() {
178  DCHECK(!CommandLine::ForCurrentProcess()->HasSwitch(
179      switches::kSyncDisableDeferredStartup));
180
181  if (!start_backend_time_.is_null())
182    return;
183
184  DVLOG(2) << "Sync deferred init fallback timer expired, starting backend.";
185  RecordTimeDeferred();
186  UMA_HISTOGRAM_ENUMERATION("Sync.Startup.DeferredInitTrigger",
187                            TRIGGER_FALLBACK_TIMER,
188                            MAX_TRIGGER_VALUE);
189  received_start_request_ = true;
190  TryStart();
191}
192
193std::string StartupController::GetBackendInitializationStateString() const {
194  if (!start_backend_time_.is_null())
195    return "Started";
196  else if (!start_up_time_.is_null())
197    return "Deferred";
198  else
199    return "Not started";
200}
201
202void StartupController::OnDataTypeRequestsSyncStartup(syncer::ModelType type) {
203  if (CommandLine::ForCurrentProcess()->HasSwitch(
204          switches::kSyncDisableDeferredStartup)) {
205    DVLOG(2) << "Ignoring data type request for sync startup: "
206             << syncer::ModelTypeToString(type);
207    return;
208  }
209
210  if (!start_backend_time_.is_null())
211    return;
212
213  DVLOG(2) << "Data type requesting sync startup: "
214           << syncer::ModelTypeToString(type);
215  // Measure the time spent waiting for init and the type that triggered it.
216  // We could measure the time spent deferred on a per-datatype basis, but
217  // for now this is probably sufficient.
218  if (!start_up_time_.is_null()) {
219    RecordTimeDeferred();
220    UMA_HISTOGRAM_ENUMERATION("Sync.Startup.TypeTriggeringInit",
221                              ModelTypeToHistogramInt(type),
222                              syncer::MODEL_TYPE_COUNT);
223    UMA_HISTOGRAM_ENUMERATION("Sync.Startup.DeferredInitTrigger",
224                              TRIGGER_DATA_TYPE_REQUEST,
225                              MAX_TRIGGER_VALUE);
226  }
227  received_start_request_ = true;
228  TryStart();
229}
230
231}  // namespace browser_sync
232