Add logging and remove pref for bootstrapping. ChromeOS always bootstraps now.

Fixes a mystery hang, or at least should help diagnose it.
BUG=http://crosbug.com/3315
TEST=manual testing

Review URL: http://codereview.chromium.org/2068013

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@47976 0039d316-1c4b-4281-b951-d872f2087c98

6 files changed, 37 insertions, 33 deletions

diff --git a/chrome/browser/sync/engine/syncapi.cc b/chrome/browser/sync/engine/syncapi.cc
index 83fa076..ecb0fa3 100644
--- a/chrome/browser/sync/engine/syncapi.cc
+++ b/chrome/browser/sync/engine/syncapi.cc
@@ -1104,7 +1104,7 @@ bool SyncManager::Init(const FilePath& database_location,
                        const char* lsid,
                        browser_sync::NotificationMethod notification_method) {
   DCHECK(post_factory);
-
+  LOG(INFO) << "SyncManager starting Init...";
   string server_string(sync_server_and_path);
   return data_->Init(database_location,
                      server_string,
@@ -1165,6 +1165,9 @@ bool SyncManager::SyncInternal::Init(
     const char* user_agent,
     const std::string& lsid,
     browser_sync::NotificationMethod notification_method) {
+
+  LOG(INFO) << "Starting SyncInternal initialization.";
+
   notification_method_ = notification_method;
   // Set up UserSettings, creating the db if necessary. We need this to
   // instantiate a URLFactory to give to the Syncer.
@@ -1176,6 +1179,8 @@ bool SyncManager::SyncInternal::Init(
 
   registrar_ = model_safe_worker_registrar;
 
+  LOG(INFO) << "Initialized sync user settings. Starting DirectoryManager.";
+
   share_.dir_manager.reset(new DirectoryManager(database_location));
 
   string client_id = user_settings_->GetClientId();
@@ -1218,6 +1223,8 @@ bool SyncManager::SyncInternal::Init(
   BridgedGaiaAuthenticator* gaia_auth = new BridgedGaiaAuthenticator(
       gaia_source, service_id, gaia_url, auth_post_factory);
 
+  LOG(INFO) << "Sync is bringing up authwatcher and SyncSessionContext.";
+
   auth_watcher_ = new AuthWatcher(dir_manager(),
                                   connection_manager(),
                                   &allstatus_,
diff --git a/chrome/browser/sync/profile_sync_service.cc b/chrome/browser/sync/profile_sync_service.cc
index fac8b5a..ae4a211 100644
--- a/chrome/browser/sync/profile_sync_service.cc
+++ b/chrome/browser/sync/profile_sync_service.cc
@@ -120,22 +120,22 @@ ProfileSyncService::~ProfileSyncService() {
 }
 
 void ProfileSyncService::Initialize() {
+  LOG(INFO) << "Starting ProfileSyncService.";
   InitSettings();
   RegisterPreferences();
 
   if (!profile()->GetPrefs()->GetBoolean(prefs::kSyncHasSetupCompleted)) {
     DisableForUser();  // Clean up in case of previous crash / setup abort.
-    // If the LSID is empty, we're in a UI test that is not testing sync
-    // behavior, so we don't want the sync service to start.
-    if (bootstrap_sync_authentication_ &&
-        !profile()->GetPrefs()->GetBoolean(prefs::kSyncBootstrappedAuth) &&
-        !GetLsidForAuthBootstraping().empty()) {
-      // If we're under Chromium OS and have never bootstrapped the
-      // authentication (ie. this is the first time we start sync for this
-      // profile,) then bootstrap it.
+
+    // Automatically start sync in Chromium OS.
+    if (bootstrap_sync_authentication_) {
+      // If the LSID is empty, we're in a CrOS UI test that is not testing sync
+      // behavior, so we don't want the sync service to start.
+      if (GetLsidForAuthBootstraping().empty()) {
+        LOG(WARNING) << "Skipping CrOS sync startup, no LSID present.";
+        return;
+      }
       StartUp();
-      profile()->GetPrefs()->SetBoolean(prefs::kSyncBootstrappedAuth, true);
-      FOR_EACH_OBSERVER(Observer, observers_, OnStateChanged());
     }
   } else {
     StartUp();
@@ -211,12 +211,6 @@ void ProfileSyncService::RegisterPreferences() {
   pref_service->RegisterBooleanPref(prefs::kSyncAutofill, enable_by_default);
   pref_service->RegisterBooleanPref(prefs::kSyncThemes, enable_by_default);
   pref_service->RegisterBooleanPref(prefs::kSyncTypedUrls, enable_by_default);
-
-  // TODO(albertb): Consider getting rid of this preference once we have a UI
-  // for per-data type disabling.
-  if (bootstrap_sync_authentication_ &&
-      !pref_service->FindPreference(prefs::kSyncBootstrappedAuth))
-    pref_service->RegisterBooleanPref(prefs::kSyncBootstrappedAuth, false);
 }
 
 void ProfileSyncService::ClearPreferences() {
@@ -282,8 +276,12 @@ void ProfileSyncService::InitializeBackend(bool delete_sync_data_folder) {
 
 void ProfileSyncService::StartUp() {
   // Don't start up multiple times.
-  if (backend_.get())
+  if (backend_.get()) {
+    LOG(INFO) << "Skipping bringing up backend host.";
     return;
+  }
+
+  LOG(INFO) << "ProfileSyncSerivce bringing up backend host.";
 
   last_synced_time_ = base::Time::FromInternalValue(
       profile_->GetPrefs()->GetInt64(prefs::kSyncLastSyncedTime));
@@ -350,6 +348,9 @@ void ProfileSyncService::DisableForUser() {
     // TODO(timsteele): Focus wizard.
     return;
   }
+
+  LOG(INFO) << "Clearing Sync DB.";
+
   // Clear prefs (including  SyncSetupHasCompleted) before shutting down so
   // PSS clients don't think we're set up while we're shutting down.
   ClearPreferences();
diff --git a/chrome/browser/sync/profile_sync_service_startup_unittest.cc b/chrome/browser/sync/profile_sync_service_startup_unittest.cc
index f8f4e7a..6e79c18 100644
--- a/chrome/browser/sync/profile_sync_service_startup_unittest.cc
+++ b/chrome/browser/sync/profile_sync_service_startup_unittest.cc
@@ -150,20 +150,10 @@ TEST_F(ProfileSyncServiceStartupBootstrapTest, SKIP_MACOSX(StartFirstTime)) {
   EXPECT_CALL(*data_type_manager, state()).
       WillOnce(Return(DataTypeManager::CONFIGURED));
   EXPECT_CALL(*data_type_manager, Stop()).Times(1);
-  EXPECT_CALL(observer_, OnStateChanged()).Times(5);
+  EXPECT_CALL(observer_, OnStateChanged()).Times(4);
 
   profile_.GetPrefs()->ClearPref(prefs::kSyncHasSetupCompleted);
   // Will start sync even though setup hasn't been completed (since
   // setup is bypassed when bootstrapping is enabled).
   service_->Initialize();
 }
-
-TEST_F(ProfileSyncServiceStartupBootstrapTest, SKIP_MACOSX(StartUserDisabled)) {
-  EXPECT_CALL(observer_, OnStateChanged()).Times(1);
-
-  profile_.GetPrefs()->ClearPref(prefs::kSyncHasSetupCompleted);
-  profile_.GetPrefs()->SetBoolean(prefs::kSyncBootstrappedAuth, true);
-  // Will not start sync because it is currently disabled, but was bootstrapped
-  // before.
-  service_->Initialize();
-}
diff --git a/chrome/browser/sync/util/user_settings_posix.cc b/chrome/browser/sync/util/user_settings_posix.cc
index 60bf0b7..da9a944 100644
--- a/chrome/browser/sync/util/user_settings_posix.cc
+++ b/chrome/browser/sync/util/user_settings_posix.cc
@@ -15,6 +15,10 @@ void UserSettings::SetAuthTokenForService(
     const std::string& email,
     const std::string& service_name,
     const std::string& long_lived_service_token) {
+
+  LOG(INFO) << "Saving auth token " << long_lived_service_token << " for "
+      << email << "for service " << service_name;
+
   std::string encrypted_service_token;
   if (!Encryptor::EncryptString(long_lived_service_token,
                                 &encrypted_service_token)) {
@@ -53,9 +57,15 @@ bool UserSettings::GetLastUserAndServiceToken(const std::string& service_name,
       return false;
     }
     *username = query.column_string(0);
+
+    LOG(INFO) << "Found service token for:" << *username
+      << " @ " << service_name << " returning: " << *service_token;
+
     return true;
   }
 
+  LOG(INFO) << "Couldn't find service token for " << service_name;
+
   return false;
 }
 
diff --git a/chrome/common/pref_names.cc b/chrome/common/pref_names.cc
index adcf924..caeb962 100644
--- a/chrome/common/pref_names.cc
+++ b/chrome/common/pref_names.cc
@@ -778,9 +778,6 @@ const wchar_t kSyncAutofill[] = L"sync.autofill";
 const wchar_t kSyncThemes[] = L"sync.themes";
 const wchar_t kSyncTypedUrls[] = L"sync.typed_urls";
 
-// Whether sync auth was bootstrapped for Chrome OS.
-const wchar_t kSyncBootstrappedAuth[] = L"sync.bootstrapped_auth";
-
 // Create web application shortcut dialog preferences.
 const wchar_t kWebAppCreateOnDesktop[] = L"browser.web_app.create_on_desktop";
 const wchar_t kWebAppCreateInAppsMenu[] =
diff --git a/chrome/common/pref_names.h b/chrome/common/pref_names.h
index 4b968b5..75600ed 100644
--- a/chrome/common/pref_names.h
+++ b/chrome/common/pref_names.h
@@ -283,7 +283,6 @@ extern const wchar_t kSyncPreferences[];
 extern const wchar_t kSyncAutofill[];
 extern const wchar_t kSyncThemes[];
 extern const wchar_t kSyncTypedUrls[];
-extern const wchar_t kSyncBootstrappedAuth[];
 
 extern const wchar_t kWebAppCreateOnDesktop[];
 extern const wchar_t kWebAppCreateInAppsMenu[];