Home | History | Annotate | Download | only in engine 
      1 // Copyright (c) 2010 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/engine/syncer_proto_util.h"
      6 
      7 #include "base/format_macros.h"
      8 #include "base/string_util.h"
      9 #include "chrome/browser/sync/engine/net/server_connection_manager.h"
     10 #include "chrome/browser/sync/engine/syncer.h"
     11 #include "chrome/browser/sync/engine/syncer_types.h"
     12 #include "chrome/browser/sync/engine/syncer_util.h"
     13 #include "chrome/browser/sync/protocol/service_constants.h"
     14 #include "chrome/browser/sync/sessions/sync_session.h"
     15 #include "chrome/browser/sync/syncable/directory_manager.h"
     16 #include "chrome/browser/sync/syncable/model_type.h"
     17 #include "chrome/browser/sync/syncable/syncable-inl.h"
     18 #include "chrome/browser/sync/syncable/syncable.h"
     19 
     20 using std::string;
     21 using std::stringstream;
     22 using syncable::BASE_VERSION;
     23 using syncable::CTIME;
     24 using syncable::ID;
     25 using syncable::IS_DEL;
     26 using syncable::IS_DIR;
     27 using syncable::IS_UNSYNCED;
     28 using syncable::MTIME;
     29 using syncable::PARENT_ID;
     30 using syncable::ScopedDirLookup;
     31 using syncable::SyncName;
     32 
     33 namespace browser_sync {
     34 using sessions::SyncSession;
     35 
     36 namespace {
     37 
     38 // Time to backoff syncing after receiving a throttled response.
     39 static const int kSyncDelayAfterThrottled = 2 * 60 * 60;  // 2 hours
     40 void LogResponseProfilingData(const ClientToServerResponse& response) {
     41   if (response.has_profiling_data()) {
     42     stringstream response_trace;
     43     response_trace << "Server response trace:";
     44 
     45     if (response.profiling_data().has_user_lookup_time()) {
     46       response_trace << " user lookup: "
     47                      << response.profiling_data().user_lookup_time() << "ms";
     48     }
     49 
     50     if (response.profiling_data().has_meta_data_write_time()) {
     51       response_trace << " meta write: "
     52                      << response.profiling_data().meta_data_write_time()
     53                      << "ms";
     54     }
     55 
     56     if (response.profiling_data().has_meta_data_read_time()) {
     57       response_trace << " meta read: "
     58                      << response.profiling_data().meta_data_read_time() << "ms";
     59     }
     60 
     61     if (response.profiling_data().has_file_data_write_time()) {
     62       response_trace << " file write: "
     63                      << response.profiling_data().file_data_write_time()
     64                      << "ms";
     65     }
     66 
     67     if (response.profiling_data().has_file_data_read_time()) {
     68       response_trace << " file read: "
     69                      << response.profiling_data().file_data_read_time() << "ms";
     70     }
     71 
     72     if (response.profiling_data().has_total_request_time()) {
     73       response_trace << " total time: "
     74                      << response.profiling_data().total_request_time() << "ms";
     75     }
     76     VLOG(1) << response_trace.str();
     77   }
     78 }
     79 
     80 }  // namespace
     81 
     82 // static
     83 void SyncerProtoUtil::HandleMigrationDoneResponse(
     84   const sync_pb::ClientToServerResponse* response,
     85   sessions::SyncSession* session) {
     86   LOG_IF(ERROR, 0 >= response->migrated_data_type_id_size())
     87       << "MIGRATION_DONE but no types specified.";
     88   syncable::ModelTypeSet to_migrate;
     89   for (int i = 0; i < response->migrated_data_type_id_size(); i++) {
     90     to_migrate.insert(syncable::GetModelTypeFromExtensionFieldNumber(
     91         response->migrated_data_type_id(i)));
     92   }
     93   session->status_controller()->set_types_needing_local_migration(to_migrate);
     94 }
     95 
     96 // static
     97 bool SyncerProtoUtil::VerifyResponseBirthday(syncable::Directory* dir,
     98     const ClientToServerResponse* response) {
     99 
    100   std::string local_birthday = dir->store_birthday();
    101 
    102   if (response->error_code() == ClientToServerResponse::CLEAR_PENDING) {
    103     // Birthday verification failures result in stopping sync and deleting
    104     // local sync data.
    105     return false;
    106   }
    107 
    108   if (local_birthday.empty()) {
    109     if (!response->has_store_birthday()) {
    110       LOG(WARNING) << "Expected a birthday on first sync.";
    111       return false;
    112     }
    113 
    114     VLOG(1) << "New store birthday: " << response->store_birthday();
    115     dir->set_store_birthday(response->store_birthday());
    116     return true;
    117   }
    118 
    119   // Error situation, but we're not stuck.
    120   if (!response->has_store_birthday()) {
    121     LOG(WARNING) << "No birthday in server response?";
    122     return true;
    123   }
    124 
    125   if (response->store_birthday() != local_birthday) {
    126     LOG(WARNING) << "Birthday changed, showing syncer stuck";
    127     return false;
    128   }
    129 
    130   return true;
    131 }
    132 
    133 // static
    134 void SyncerProtoUtil::AddRequestBirthday(syncable::Directory* dir,
    135                                          ClientToServerMessage* msg) {
    136   if (!dir->store_birthday().empty())
    137     msg->set_store_birthday(dir->store_birthday());
    138 }
    139 
    140 // static
    141 bool SyncerProtoUtil::PostAndProcessHeaders(ServerConnectionManager* scm,
    142                                             sessions::SyncSession* session,
    143                                             const ClientToServerMessage& msg,
    144                                             ClientToServerResponse* response) {
    145 
    146   std::string tx, rx;
    147   msg.SerializeToString(&tx);
    148 
    149   HttpResponse http_response;
    150   ServerConnectionManager::PostBufferParams params = {
    151     tx, &rx, &http_response
    152   };
    153 
    154   ScopedServerStatusWatcher server_status_watcher(scm, &http_response);
    155   if (!scm->PostBufferWithCachedAuth(&params, &server_status_watcher)) {
    156     LOG(WARNING) << "Error posting from syncer:" << http_response;
    157     return false;
    158   }
    159 
    160   std::string new_token = http_response.update_client_auth_header;
    161   if (!new_token.empty()) {
    162     SyncEngineEvent event(SyncEngineEvent::UPDATED_TOKEN);
    163     event.updated_token = new_token;
    164     session->context()->NotifyListeners(event);
    165   }
    166 
    167   if (response->ParseFromString(rx)) {
    168     // TODO(tim): This is an egregious layering violation (bug 35060).
    169     switch (response->error_code()) {
    170       case ClientToServerResponse::ACCESS_DENIED:
    171       case ClientToServerResponse::AUTH_INVALID:
    172       case ClientToServerResponse::USER_NOT_ACTIVATED:
    173         // Fires on ScopedServerStatusWatcher
    174         http_response.server_status = HttpResponse::SYNC_AUTH_ERROR;
    175         return false;
    176       default:
    177         return true;
    178     }
    179   }
    180 
    181   return false;
    182 }
    183 
    184 namespace {
    185 
    186 // Helper function for an assertion in PostClientToServerMessage.
    187 bool IsVeryFirstGetUpdates(const ClientToServerMessage& message) {
    188   if (!message.has_get_updates())
    189     return false;
    190   DCHECK_LT(0, message.get_updates().from_progress_marker_size());
    191   for (int i = 0; i < message.get_updates().from_progress_marker_size(); ++i) {
    192     if (!message.get_updates().from_progress_marker(i).token().empty())
    193       return false;
    194   }
    195   return true;
    196 }
    197 
    198 }  // namespace
    199 
    200 // static
    201 bool SyncerProtoUtil::PostClientToServerMessage(
    202     const ClientToServerMessage& msg,
    203     ClientToServerResponse* response,
    204     SyncSession* session) {
    205 
    206   CHECK(response);
    207   DCHECK(!msg.get_updates().has_from_timestamp());  // Deprecated.
    208   DCHECK(!msg.get_updates().has_requested_types());  // Deprecated.
    209   DCHECK(msg.has_store_birthday() || IsVeryFirstGetUpdates(msg))
    210       << "Must call AddRequestBirthday to set birthday.";
    211 
    212   ScopedDirLookup dir(session->context()->directory_manager(),
    213       session->context()->account_name());
    214   if (!dir.good())
    215     return false;
    216 
    217   if (!PostAndProcessHeaders(session->context()->connection_manager(), session,
    218                              msg, response))
    219     return false;
    220 
    221   if (!VerifyResponseBirthday(dir, response)) {
    222     session->status_controller()->set_syncer_stuck(true);
    223     session->delegate()->OnShouldStopSyncingPermanently();
    224     return false;
    225   }
    226 
    227   switch (response->error_code()) {
    228     case ClientToServerResponse::UNKNOWN:
    229       LOG(WARNING) << "Sync protocol out-of-date. The server is using a more "
    230                    << "recent version.";
    231       return false;
    232     case ClientToServerResponse::SUCCESS:
    233       LogResponseProfilingData(*response);
    234       return true;
    235     case ClientToServerResponse::THROTTLED:
    236       LOG(WARNING) << "Client silenced by server.";
    237       session->delegate()->OnSilencedUntil(base::TimeTicks::Now() +
    238           base::TimeDelta::FromSeconds(kSyncDelayAfterThrottled));
    239       return false;
    240     case ClientToServerResponse::TRANSIENT_ERROR:
    241       return false;
    242     case ClientToServerResponse::MIGRATION_DONE:
    243       HandleMigrationDoneResponse(response, session);
    244       return false;
    245     case ClientToServerResponse::USER_NOT_ACTIVATED:
    246     case ClientToServerResponse::AUTH_INVALID:
    247     case ClientToServerResponse::ACCESS_DENIED:
    248       // WARNING: PostAndProcessHeaders contains a hack for this case.
    249       LOG(WARNING) << "SyncerProtoUtil: Authentication expired.";
    250       // TODO(sync): Was this meant to be a fall-through?
    251     default:
    252       NOTREACHED();
    253       return false;
    254   }
    255 }
    256 
    257 // static
    258 bool SyncerProtoUtil::Compare(const syncable::Entry& local_entry,
    259                               const SyncEntity& server_entry) {
    260   const std::string name = NameFromSyncEntity(server_entry);
    261 
    262   CHECK(local_entry.Get(ID) == server_entry.id()) <<
    263       " SyncerProtoUtil::Compare precondition not met.";
    264   CHECK(server_entry.version() == local_entry.Get(BASE_VERSION)) <<
    265       " SyncerProtoUtil::Compare precondition not met.";
    266   CHECK(!local_entry.Get(IS_UNSYNCED)) <<
    267       " SyncerProtoUtil::Compare precondition not met.";
    268 
    269   if (local_entry.Get(IS_DEL) && server_entry.deleted())
    270     return true;
    271   if (!ClientAndServerTimeMatch(local_entry.Get(CTIME), server_entry.ctime())) {
    272     LOG(WARNING) << "ctime mismatch";
    273     return false;
    274   }
    275 
    276   // These checks are somewhat prolix, but they're easier to debug than a big
    277   // boolean statement.
    278   string client_name = local_entry.Get(syncable::NON_UNIQUE_NAME);
    279   if (client_name != name) {
    280     LOG(WARNING) << "Client name mismatch";
    281     return false;
    282   }
    283   if (local_entry.Get(PARENT_ID) != server_entry.parent_id()) {
    284     LOG(WARNING) << "Parent ID mismatch";
    285     return false;
    286   }
    287   if (local_entry.Get(IS_DIR) != server_entry.IsFolder()) {
    288     LOG(WARNING) << "Dir field mismatch";
    289     return false;
    290   }
    291   if (local_entry.Get(IS_DEL) != server_entry.deleted()) {
    292     LOG(WARNING) << "Deletion mismatch";
    293     return false;
    294   }
    295   if (!local_entry.Get(IS_DIR) &&
    296       !ClientAndServerTimeMatch(local_entry.Get(MTIME),
    297                                 server_entry.mtime())) {
    298     LOG(WARNING) << "mtime mismatch";
    299     return false;
    300   }
    301 
    302   return true;
    303 }
    304 
    305 // static
    306 void SyncerProtoUtil::CopyProtoBytesIntoBlob(const std::string& proto_bytes,
    307                                              syncable::Blob* blob) {
    308   syncable::Blob proto_blob(proto_bytes.begin(), proto_bytes.end());
    309   blob->swap(proto_blob);
    310 }
    311 
    312 // static
    313 bool SyncerProtoUtil::ProtoBytesEqualsBlob(const std::string& proto_bytes,
    314                                            const syncable::Blob& blob) {
    315   if (proto_bytes.size() != blob.size())
    316     return false;
    317   return std::equal(proto_bytes.begin(), proto_bytes.end(), blob.begin());
    318 }
    319 
    320 // static
    321 void SyncerProtoUtil::CopyBlobIntoProtoBytes(const syncable::Blob& blob,
    322                                              std::string* proto_bytes) {
    323   std::string blob_string(blob.begin(), blob.end());
    324   proto_bytes->swap(blob_string);
    325 }
    326 
    327 // static
    328 const std::string& SyncerProtoUtil::NameFromSyncEntity(
    329     const sync_pb::SyncEntity& entry) {
    330   if (entry.has_non_unique_name())
    331     return entry.non_unique_name();
    332   return entry.name();
    333 }
    334 
    335 // static
    336 const std::string& SyncerProtoUtil::NameFromCommitEntryResponse(
    337     const CommitResponse_EntryResponse& entry) {
    338   if (entry.has_non_unique_name())
    339     return entry.non_unique_name();
    340   return entry.name();
    341 }
    342 
    343 std::string SyncerProtoUtil::SyncEntityDebugString(
    344     const sync_pb::SyncEntity& entry) {
    345   return StringPrintf("id: %s, parent_id: %s, "
    346                       "version: %"PRId64"d, "
    347                       "mtime: %" PRId64"d (client: %" PRId64"d), "
    348                       "ctime: %" PRId64"d (client: %" PRId64"d), "
    349                       "name: %s, sync_timestamp: %" PRId64"d, "
    350                       "%s ",
    351                       entry.id_string().c_str(),
    352                       entry.parent_id_string().c_str(),
    353                       entry.version(),
    354                       entry.mtime(), ServerTimeToClientTime(entry.mtime()),
    355                       entry.ctime(), ServerTimeToClientTime(entry.ctime()),
    356                       entry.name().c_str(), entry.sync_timestamp(),
    357                       entry.deleted() ? "deleted, ":"");
    358 }
    359 
    360 namespace {
    361 std::string GetUpdatesResponseString(
    362     const sync_pb::GetUpdatesResponse& response) {
    363   std::string output;
    364   output.append("GetUpdatesResponse:\n");
    365   for (int i = 0; i < response.entries_size(); i++) {
    366     output.append(SyncerProtoUtil::SyncEntityDebugString(response.entries(i)));
    367     output.append("\n");
    368   }
    369   return output;
    370 }
    371 }  // namespace
    372 
    373 std::string SyncerProtoUtil::ClientToServerResponseDebugString(
    374     const sync_pb::ClientToServerResponse& response) {
    375   // Add more handlers as needed.
    376   std::string output;
    377   if (response.has_get_updates())
    378     output.append(GetUpdatesResponseString(response.get_updates()));
    379   return output;
    380 }
    381 
    382 }  // namespace browser_sync
    383