sync/engine/syncer_proto_util.cc

   1 // Copyright (c) 2012 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 "sync/engine/syncer_proto_util.h"
   6
   7 #include "base/format_macros.h"
   8 #include "base/stringprintf.h"
   9 #include "sync/engine/net/server_connection_manager.h"
  10 #include "sync/engine/syncer.h"
  11 #include "sync/engine/syncer_types.h"
  12 #include "sync/engine/throttled_data_type_tracker.h"
  13 #include "sync/engine/traffic_logger.h"
  14 #include "sync/internal_api/public/base/model_type.h"
  15 #include "sync/protocol/sync.pb.h"
  16 #include "sync/protocol/sync_enums.pb.h"
  17 #include "sync/protocol/sync_protocol_error.h"
  18 #include "sync/sessions/sync_session.h"
  19 #include "sync/syncable/directory.h"
  20 #include "sync/syncable/entry.h"
  21 #include "sync/syncable/syncable-inl.h"
  22 #include "sync/util/time.h"
  23
  24 using std::string;
  25 using std::stringstream;
  26
  27 namespace syncer {
  28
  29 using sessions::SyncSession;
  30 using syncable::BASE_VERSION;
  31 using syncable::CTIME;
  32 using syncable::ID;
  33 using syncable::IS_DEL;
  34 using syncable::IS_DIR;
  35 using syncable::IS_UNSYNCED;
  36 using syncable::MTIME;
  37 using syncable::PARENT_ID;
  38
  39 namespace {
  40
  41 // Time to backoff syncing after receiving a throttled response.
  42 const int kSyncDelayAfterThrottled = 2 * 60 * 60;  // 2 hours
  43
  44 void LogResponseProfilingData(const ClientToServerResponse& response) {
  45   if (response.has_profiling_data()) {
  46     stringstream response_trace;
  47     response_trace << "Server response trace:";
  48
  49     if (response.profiling_data().has_user_lookup_time()) {
  50       response_trace << " user lookup: "
  51                      << response.profiling_data().user_lookup_time() << "ms";
  52     }
  53
  54     if (response.profiling_data().has_meta_data_write_time()) {
  55       response_trace << " meta write: "
  56                      << response.profiling_data().meta_data_write_time()
  57                      << "ms";
  58     }
  59
  60     if (response.profiling_data().has_meta_data_read_time()) {
  61       response_trace << " meta read: "
  62                      << response.profiling_data().meta_data_read_time() << "ms";
  63     }
  64
  65     if (response.profiling_data().has_file_data_write_time()) {
  66       response_trace << " file write: "
  67                      << response.profiling_data().file_data_write_time()
  68                      << "ms";
  69     }
  70
  71     if (response.profiling_data().has_file_data_read_time()) {
  72       response_trace << " file read: "
  73                      << response.profiling_data().file_data_read_time() << "ms";
  74     }
  75
  76     if (response.profiling_data().has_total_request_time()) {
  77       response_trace << " total time: "
  78                      << response.profiling_data().total_request_time() << "ms";
  79     }
  80     DVLOG(1) << response_trace.str();
  81   }
  82 }
  83
  84 SyncerError ServerConnectionErrorAsSyncerError(
  85     const HttpResponse::ServerConnectionCode server_status) {
  86   switch (server_status) {
  87     case HttpResponse::CONNECTION_UNAVAILABLE:
  88       return NETWORK_CONNECTION_UNAVAILABLE;
  89     case HttpResponse::IO_ERROR:
  90       return NETWORK_IO_ERROR;
  91     case HttpResponse::SYNC_SERVER_ERROR:
  92       // FIXME what does this mean?
  93       return SYNC_SERVER_ERROR;
  94     case HttpResponse::SYNC_AUTH_ERROR:
  95       return SYNC_AUTH_ERROR;
  96     case HttpResponse::RETRY:
  97       return SERVER_RETURN_TRANSIENT_ERROR;
  98     case HttpResponse::SERVER_CONNECTION_OK:
  99     case HttpResponse::NONE:
 100     default:
 101       NOTREACHED();
 102       return UNSET;
 103   }
 104 }
 105
 106 }  // namespace
 107
 108 // static
 109 void SyncerProtoUtil::HandleMigrationDoneResponse(
 110   const sync_pb::ClientToServerResponse* response,
 111   sessions::SyncSession* session) {
 112   LOG_IF(ERROR, 0 >= response->migrated_data_type_id_size())
 113       << "MIGRATION_DONE but no types specified.";
 114   syncer::ModelTypeSet to_migrate;
 115   for (int i = 0; i < response->migrated_data_type_id_size(); i++) {
 116     to_migrate.Put(syncer::GetModelTypeFromSpecificsFieldNumber(
 117         response->migrated_data_type_id(i)));
 118   }
 119   // TODO(akalin): This should be a set union.
 120   session->mutable_status_controller()->
 121       set_types_needing_local_migration(to_migrate);
 122 }
 123
 124 // static
 125 bool SyncerProtoUtil::VerifyResponseBirthday(syncable::Directory* dir,
 126     const ClientToServerResponse* response) {
 127
 128   std::string local_birthday = dir->store_birthday();
 129
 130   if (local_birthday.empty()) {
 131     if (!response->has_store_birthday()) {
 132       LOG(WARNING) << "Expected a birthday on first sync.";
 133       return false;
 134     }
 135
 136     DVLOG(1) << "New store birthday: " << response->store_birthday();
 137     dir->set_store_birthday(response->store_birthday());
 138     return true;
 139   }
 140
 141   // Error situation, but we're not stuck.
 142   if (!response->has_store_birthday()) {
 143     LOG(WARNING) << "No birthday in server response?";
 144     return true;
 145   }
 146
 147   if (response->store_birthday() != local_birthday) {
 148     LOG(WARNING) << "Birthday changed, showing syncer stuck";
 149     return false;
 150   }
 151
 152   return true;
 153 }
 154
 155 // static
 156 void SyncerProtoUtil::AddRequestBirthday(syncable::Directory* dir,
 157                                          ClientToServerMessage* msg) {
 158   if (!dir->store_birthday().empty())
 159     msg->set_store_birthday(dir->store_birthday());
 160 }
 161
 162 // static
 163 bool SyncerProtoUtil::PostAndProcessHeaders(ServerConnectionManager* scm,
 164                                             sessions::SyncSession* session,
 165                                             const ClientToServerMessage& msg,
 166                                             ClientToServerResponse* response) {
 167   ServerConnectionManager::PostBufferParams params;
 168   msg.SerializeToString(&params.buffer_in);
 169
 170   ScopedServerStatusWatcher server_status_watcher(scm, &params.response);
 171   // Fills in params.buffer_out and params.response.
 172   if (!scm->PostBufferWithCachedAuth(&params, &server_status_watcher)) {
 173     LOG(WARNING) << "Error posting from syncer:" << params.response;
 174     return false;
 175   }
 176
 177   std::string new_token = params.response.update_client_auth_header;
 178   if (!new_token.empty()) {
 179     SyncEngineEvent event(SyncEngineEvent::UPDATED_TOKEN);
 180     event.updated_token = new_token;
 181     session->context()->NotifyListeners(event);
 182   }
 183
 184   if (response->ParseFromString(params.buffer_out)) {
 185     // TODO(tim): This is an egregious layering violation (bug 35060).
 186     switch (response->error_code()) {
 187       case sync_pb::SyncEnums::ACCESS_DENIED:
 188       case sync_pb::SyncEnums::AUTH_INVALID:
 189       case sync_pb::SyncEnums::USER_NOT_ACTIVATED:
 190         // Fires on ScopedServerStatusWatcher
 191         params.response.server_status = HttpResponse::SYNC_AUTH_ERROR;
 192         return false;
 193       default:
 194         return true;
 195     }
 196   }
 197
 198   return false;
 199 }
 200
 201 base::TimeDelta SyncerProtoUtil::GetThrottleDelay(
 202     const sync_pb::ClientToServerResponse& response) {
 203   base::TimeDelta throttle_delay =
 204       base::TimeDelta::FromSeconds(kSyncDelayAfterThrottled);
 205   if (response.has_client_command()) {
 206     const sync_pb::ClientCommand& command = response.client_command();
 207     if (command.has_throttle_delay_seconds()) {
 208       throttle_delay =
 209           base::TimeDelta::FromSeconds(command.throttle_delay_seconds());
 210     }
 211   }
 212   return throttle_delay;
 213 }
 214
 215 void SyncerProtoUtil::HandleThrottleError(
 216     const SyncProtocolError& error,
 217     const base::TimeTicks& throttled_until,
 218     ThrottledDataTypeTracker* tracker,
 219     sessions::SyncSession::Delegate* delegate) {
 220   DCHECK_EQ(error.error_type, syncer::THROTTLED);
 221   if (error.error_data_types.Empty()) {
 222     // No datatypes indicates the client should be completely throttled.
 223     delegate->OnSilencedUntil(throttled_until);
 224   } else {
 225     tracker->SetUnthrottleTime(error.error_data_types, throttled_until);
 226   }
 227 }
 228
 229 namespace {
 230
 231 // Helper function for an assertion in PostClientToServerMessage.
 232 bool IsVeryFirstGetUpdates(const ClientToServerMessage& message) {
 233   if (!message.has_get_updates())
 234     return false;
 235   DCHECK_LT(0, message.get_updates().from_progress_marker_size());
 236   for (int i = 0; i < message.get_updates().from_progress_marker_size(); ++i) {
 237     if (!message.get_updates().from_progress_marker(i).token().empty())
 238       return false;
 239   }
 240   return true;
 241 }
 242
 243 SyncProtocolErrorType ConvertSyncProtocolErrorTypePBToLocalType(
 244     const sync_pb::SyncEnums::ErrorType& error_type) {
 245   switch (error_type) {
 246     case sync_pb::SyncEnums::SUCCESS:
 247       return syncer::SYNC_SUCCESS;
 248     case sync_pb::SyncEnums::NOT_MY_BIRTHDAY:
 249       return syncer::NOT_MY_BIRTHDAY;
 250     case sync_pb::SyncEnums::THROTTLED:
 251       return syncer::THROTTLED;
 252     case sync_pb::SyncEnums::CLEAR_PENDING:
 253       return syncer::CLEAR_PENDING;
 254     case sync_pb::SyncEnums::TRANSIENT_ERROR:
 255       return syncer::TRANSIENT_ERROR;
 256     case sync_pb::SyncEnums::MIGRATION_DONE:
 257       return syncer::MIGRATION_DONE;
 258     case sync_pb::SyncEnums::UNKNOWN:
 259       return syncer::UNKNOWN_ERROR;
 260     case sync_pb::SyncEnums::USER_NOT_ACTIVATED:
 261     case sync_pb::SyncEnums::AUTH_INVALID:
 262     case sync_pb::SyncEnums::ACCESS_DENIED:
 263       return syncer::INVALID_CREDENTIAL;
 264     default:
 265       NOTREACHED();
 266       return syncer::UNKNOWN_ERROR;
 267   }
 268 }
 269
 270 syncer::ClientAction ConvertClientActionPBToLocalClientAction(
 271     const sync_pb::SyncEnums::Action& action) {
 272   switch (action) {
 273     case sync_pb::SyncEnums::UPGRADE_CLIENT:
 274       return syncer::UPGRADE_CLIENT;
 275     case sync_pb::SyncEnums::CLEAR_USER_DATA_AND_RESYNC:
 276       return syncer::CLEAR_USER_DATA_AND_RESYNC;
 277     case sync_pb::SyncEnums::ENABLE_SYNC_ON_ACCOUNT:
 278       return syncer::ENABLE_SYNC_ON_ACCOUNT;
 279     case sync_pb::SyncEnums::STOP_AND_RESTART_SYNC:
 280       return syncer::STOP_AND_RESTART_SYNC;
 281     case sync_pb::SyncEnums::DISABLE_SYNC_ON_CLIENT:
 282       return syncer::DISABLE_SYNC_ON_CLIENT;
 283     case sync_pb::SyncEnums::UNKNOWN_ACTION:
 284       return syncer::UNKNOWN_ACTION;
 285     default:
 286       NOTREACHED();
 287       return syncer::UNKNOWN_ACTION;
 288   }
 289 }
 290
 291 syncer::SyncProtocolError ConvertErrorPBToLocalType(
 292     const sync_pb::ClientToServerResponse::Error& error) {
 293   syncer::SyncProtocolError sync_protocol_error;
 294   sync_protocol_error.error_type = ConvertSyncProtocolErrorTypePBToLocalType(
 295       error.error_type());
 296   sync_protocol_error.error_description = error.error_description();
 297   sync_protocol_error.url = error.url();
 298   sync_protocol_error.action = ConvertClientActionPBToLocalClientAction(
 299       error.action());
 300
 301   if (error.error_data_type_ids_size() > 0) {
 302     // THROTTLED is currently the only error code that uses |error_data_types|.
 303     DCHECK_EQ(error.error_type(), sync_pb::SyncEnums::THROTTLED);
 304     for (int i = 0; i < error.error_data_type_ids_size(); ++i) {
 305       sync_protocol_error.error_data_types.Put(
 306           syncer::GetModelTypeFromSpecificsFieldNumber(
 307               error.error_data_type_ids(i)));
 308     }
 309   }
 310
 311   return sync_protocol_error;
 312 }
 313
 314 // TODO(lipalani) : Rename these function names as per the CR for issue 7740067.
 315 syncer::SyncProtocolError ConvertLegacyErrorCodeToNewError(
 316     const sync_pb::SyncEnums::ErrorType& error_type) {
 317   syncer::SyncProtocolError error;
 318   error.error_type = ConvertSyncProtocolErrorTypePBToLocalType(error_type);
 319   if (error_type == sync_pb::SyncEnums::CLEAR_PENDING ||
 320       error_type == sync_pb::SyncEnums::NOT_MY_BIRTHDAY) {
 321       error.action = syncer::DISABLE_SYNC_ON_CLIENT;
 322   }  // There is no other action we can compute for legacy server.
 323   return error;
 324 }
 325
 326 }  // namespace
 327
 328 // static
 329 SyncerError SyncerProtoUtil::PostClientToServerMessage(
 330     const ClientToServerMessage& msg,
 331     ClientToServerResponse* response,
 332     SyncSession* session) {
 333
 334   CHECK(response);
 335   DCHECK(!msg.get_updates().has_from_timestamp());  // Deprecated.
 336   DCHECK(!msg.get_updates().has_requested_types());  // Deprecated.
 337   DCHECK(msg.has_store_birthday() || IsVeryFirstGetUpdates(msg))
 338       << "Must call AddRequestBirthday to set birthday.";
 339
 340   syncable::Directory* dir = session->context()->directory();
 341
 342   LogClientToServerMessage(msg);
 343   session->context()->traffic_recorder()->RecordClientToServerMessage(msg);
 344   if (!PostAndProcessHeaders(session->context()->connection_manager(), session,
 345                              msg, response)) {
 346     // There was an error establishing communication with the server.
 347     // We can not proceed beyond this point.
 348     const syncer::HttpResponse::ServerConnectionCode server_status =
 349         session->context()->connection_manager()->server_status();
 350
 351     DCHECK_NE(server_status, syncer::HttpResponse::NONE);
 352     DCHECK_NE(server_status, syncer::HttpResponse::SERVER_CONNECTION_OK);
 353
 354     return ServerConnectionErrorAsSyncerError(server_status);
 355   }
 356
 357   LogClientToServerResponse(*response);
 358   session->context()->traffic_recorder()->RecordClientToServerResponse(
 359       *response);
 360
 361   syncer::SyncProtocolError sync_protocol_error;
 362
 363   // Birthday mismatch overrides any error that is sent by the server.
 364   if (!VerifyResponseBirthday(dir, response)) {
 365     sync_protocol_error.error_type = syncer::NOT_MY_BIRTHDAY;
 366      sync_protocol_error.action =
 367          syncer::DISABLE_SYNC_ON_CLIENT;
 368   } else if (response->has_error()) {
 369     // This is a new server. Just get the error from the protocol.
 370     sync_protocol_error = ConvertErrorPBToLocalType(response->error());
 371   } else {
 372     // Legacy server implementation. Compute the error based on |error_code|.
 373     sync_protocol_error = ConvertLegacyErrorCodeToNewError(
 374         response->error_code());
 375   }
 376
 377   // Now set the error into the status so the layers above us could read it.
 378   sessions::StatusController* status = session->mutable_status_controller();
 379   status->set_sync_protocol_error(sync_protocol_error);
 380
 381   // Inform the delegate of the error we got.
 382   session->delegate()->OnSyncProtocolError(session->TakeSnapshot());
 383
 384   // Now do any special handling for the error type and decide on the return
 385   // value.
 386   switch (sync_protocol_error.error_type) {
 387     case syncer::UNKNOWN_ERROR:
 388       LOG(WARNING) << "Sync protocol out-of-date. The server is using a more "
 389                    << "recent version.";
 390       return SERVER_RETURN_UNKNOWN_ERROR;
 391     case syncer::SYNC_SUCCESS:
 392       LogResponseProfilingData(*response);
 393       return SYNCER_OK;
 394     case syncer::THROTTLED:
 395       LOG(WARNING) << "Client silenced by server.";
 396       HandleThrottleError(sync_protocol_error,
 397                           base::TimeTicks::Now() + GetThrottleDelay(*response),
 398                           session->context()->throttled_data_type_tracker(),
 399                           session->delegate());
 400       return SERVER_RETURN_THROTTLED;
 401     case syncer::TRANSIENT_ERROR:
 402       return SERVER_RETURN_TRANSIENT_ERROR;
 403     case syncer::MIGRATION_DONE:
 404       HandleMigrationDoneResponse(response, session);
 405       return SERVER_RETURN_MIGRATION_DONE;
 406     case syncer::CLEAR_PENDING:
 407       return SERVER_RETURN_CLEAR_PENDING;
 408     case syncer::NOT_MY_BIRTHDAY:
 409       return SERVER_RETURN_NOT_MY_BIRTHDAY;
 410     default:
 411       NOTREACHED();
 412       return UNSET;
 413   }
 414 }
 415
 416 // static
 417 bool SyncerProtoUtil::Compare(const syncable::Entry& local_entry,
 418                               const SyncEntity& server_entry) {
 419   const std::string name = NameFromSyncEntity(server_entry);
 420
 421   CHECK(local_entry.Get(ID) == server_entry.id()) <<
 422       " SyncerProtoUtil::Compare precondition not met.";
 423   CHECK(server_entry.version() == local_entry.Get(BASE_VERSION)) <<
 424       " SyncerProtoUtil::Compare precondition not met.";
 425   CHECK(!local_entry.Get(IS_UNSYNCED)) <<
 426       " SyncerProtoUtil::Compare precondition not met.";
 427
 428   if (local_entry.Get(IS_DEL) && server_entry.deleted())
 429     return true;
 430   if (local_entry.Get(CTIME) != ProtoTimeToTime(server_entry.ctime())) {
 431     LOG(WARNING) << "ctime mismatch";
 432     return false;
 433   }
 434
 435   // These checks are somewhat prolix, but they're easier to debug than a big
 436   // boolean statement.
 437   string client_name = local_entry.Get(syncable::NON_UNIQUE_NAME);
 438   if (client_name != name) {
 439     LOG(WARNING) << "Client name mismatch";
 440     return false;
 441   }
 442   if (local_entry.Get(PARENT_ID) != server_entry.parent_id()) {
 443     LOG(WARNING) << "Parent ID mismatch";
 444     return false;
 445   }
 446   if (local_entry.Get(IS_DIR) != server_entry.IsFolder()) {
 447     LOG(WARNING) << "Dir field mismatch";
 448     return false;
 449   }
 450   if (local_entry.Get(IS_DEL) != server_entry.deleted()) {
 451     LOG(WARNING) << "Deletion mismatch";
 452     return false;
 453   }
 454   if (!local_entry.Get(IS_DIR) &&
 455       (local_entry.Get(MTIME) != ProtoTimeToTime(server_entry.mtime()))) {
 456     LOG(WARNING) << "mtime mismatch";
 457     return false;
 458   }
 459
 460   return true;
 461 }
 462
 463 // static
 464 void SyncerProtoUtil::CopyProtoBytesIntoBlob(const std::string& proto_bytes,
 465                                              syncable::Blob* blob) {
 466   syncable::Blob proto_blob(proto_bytes.begin(), proto_bytes.end());
 467   blob->swap(proto_blob);
 468 }
 469
 470 // static
 471 bool SyncerProtoUtil::ProtoBytesEqualsBlob(const std::string& proto_bytes,
 472                                            const syncable::Blob& blob) {
 473   if (proto_bytes.size() != blob.size())
 474     return false;
 475   return std::equal(proto_bytes.begin(), proto_bytes.end(), blob.begin());
 476 }
 477
 478 // static
 479 void SyncerProtoUtil::CopyBlobIntoProtoBytes(const syncable::Blob& blob,
 480                                              std::string* proto_bytes) {
 481   std::string blob_string(blob.begin(), blob.end());
 482   proto_bytes->swap(blob_string);
 483 }
 484
 485 // static
 486 const std::string& SyncerProtoUtil::NameFromSyncEntity(
 487     const sync_pb::SyncEntity& entry) {
 488   if (entry.has_non_unique_name())
 489     return entry.non_unique_name();
 490   return entry.name();
 491 }
 492
 493 // static
 494 const std::string& SyncerProtoUtil::NameFromCommitEntryResponse(
 495     const CommitResponse_EntryResponse& entry) {
 496   if (entry.has_non_unique_name())
 497     return entry.non_unique_name();
 498   return entry.name();
 499 }
 500
 501 std::string SyncerProtoUtil::SyncEntityDebugString(
 502     const sync_pb::SyncEntity& entry) {
 503   const std::string& mtime_str =
 504       GetTimeDebugString(ProtoTimeToTime(entry.mtime()));
 505   const std::string& ctime_str =
 506       GetTimeDebugString(ProtoTimeToTime(entry.ctime()));
 507   return base::StringPrintf(
 508       "id: %s, parent_id: %s, "
 509       "version: %"PRId64"d, "
 510       "mtime: %" PRId64"d (%s), "
 511       "ctime: %" PRId64"d (%s), "
 512       "name: %s, sync_timestamp: %" PRId64"d, "
 513       "%s ",
 514       entry.id_string().c_str(),
 515       entry.parent_id_string().c_str(),
 516       entry.version(),
 517       entry.mtime(), mtime_str.c_str(),
 518       entry.ctime(), ctime_str.c_str(),
 519       entry.name().c_str(), entry.sync_timestamp(),
 520       entry.deleted() ? "deleted, ":"");
 521 }
 522
 523 namespace {
 524 std::string GetUpdatesResponseString(
 525     const sync_pb::GetUpdatesResponse& response) {
 526   std::string output;
 527   output.append("GetUpdatesResponse:\n");
 528   for (int i = 0; i < response.entries_size(); i++) {
 529     output.append(SyncerProtoUtil::SyncEntityDebugString(response.entries(i)));
 530     output.append("\n");
 531   }
 532   return output;
 533 }
 534 }  // namespace
 535
 536 std::string SyncerProtoUtil::ClientToServerResponseDebugString(
 537     const sync_pb::ClientToServerResponse& response) {
 538   // Add more handlers as needed.
 539   std::string output;
 540   if (response.has_get_updates())
 541     output.append(GetUpdatesResponseString(response.get_updates()));
 542   return output;
 543 }
 544
 545 }  // namespace syncer