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/strings/stringprintf.h" 9 #include "google_apis/google_api_keys.h" 10 #include "sync/engine/net/server_connection_manager.h" 11 #include "sync/engine/syncer.h" 12 #include "sync/engine/syncer_types.h" 13 #include "sync/engine/traffic_logger.h" 14 #include "sync/internal_api/public/base/model_type.h" 15 #include "sync/protocol/sync_enums.pb.h" 16 #include "sync/protocol/sync_protocol_error.h" 17 #include "sync/sessions/sync_session.h" 18 #include "sync/syncable/directory.h" 19 #include "sync/syncable/entry.h" 20 #include "sync/syncable/syncable-inl.h" 21 #include "sync/syncable/syncable_proto_util.h" 22 #include "sync/util/time.h" 23 24 using std::string; 25 using std::stringstream; 26 using sync_pb::ClientToServerMessage; 27 using sync_pb::ClientToServerResponse; 28 29 namespace syncer { 30 31 using sessions::SyncSession; 32 using syncable::BASE_VERSION; 33 using syncable::CTIME; 34 using syncable::ID; 35 using syncable::IS_DEL; 36 using syncable::IS_DIR; 37 using syncable::IS_UNSYNCED; 38 using syncable::MTIME; 39 using syncable::PARENT_ID; 40 41 namespace { 42 43 // Time to backoff syncing after receiving a throttled response. 44 const int kSyncDelayAfterThrottled = 2 * 60 * 60; // 2 hours 45 46 void LogResponseProfilingData(const ClientToServerResponse& response) { 47 if (response.has_profiling_data()) { 48 stringstream response_trace; 49 response_trace << "Server response trace:"; 50 51 if (response.profiling_data().has_user_lookup_time()) { 52 response_trace << " user lookup: " 53 << response.profiling_data().user_lookup_time() << "ms"; 54 } 55 56 if (response.profiling_data().has_meta_data_write_time()) { 57 response_trace << " meta write: " 58 << response.profiling_data().meta_data_write_time() 59 << "ms"; 60 } 61 62 if (response.profiling_data().has_meta_data_read_time()) { 63 response_trace << " meta read: " 64 << response.profiling_data().meta_data_read_time() << "ms"; 65 } 66 67 if (response.profiling_data().has_file_data_write_time()) { 68 response_trace << " file write: " 69 << response.profiling_data().file_data_write_time() 70 << "ms"; 71 } 72 73 if (response.profiling_data().has_file_data_read_time()) { 74 response_trace << " file read: " 75 << response.profiling_data().file_data_read_time() << "ms"; 76 } 77 78 if (response.profiling_data().has_total_request_time()) { 79 response_trace << " total time: " 80 << response.profiling_data().total_request_time() << "ms"; 81 } 82 DVLOG(1) << response_trace.str(); 83 } 84 } 85 86 SyncerError ServerConnectionErrorAsSyncerError( 87 const HttpResponse::ServerConnectionCode server_status) { 88 switch (server_status) { 89 case HttpResponse::CONNECTION_UNAVAILABLE: 90 return NETWORK_CONNECTION_UNAVAILABLE; 91 case HttpResponse::IO_ERROR: 92 return NETWORK_IO_ERROR; 93 case HttpResponse::SYNC_SERVER_ERROR: 94 // FIXME what does this mean? 95 return SYNC_SERVER_ERROR; 96 case HttpResponse::SYNC_AUTH_ERROR: 97 return SYNC_AUTH_ERROR; 98 case HttpResponse::RETRY: 99 return SERVER_RETURN_TRANSIENT_ERROR; 100 case HttpResponse::SERVER_CONNECTION_OK: 101 case HttpResponse::NONE: 102 default: 103 NOTREACHED(); 104 return UNSET; 105 } 106 } 107 108 SyncProtocolErrorType ConvertSyncProtocolErrorTypePBToLocalType( 109 const sync_pb::SyncEnums::ErrorType& error_type) { 110 switch (error_type) { 111 case sync_pb::SyncEnums::SUCCESS: 112 return SYNC_SUCCESS; 113 case sync_pb::SyncEnums::NOT_MY_BIRTHDAY: 114 return NOT_MY_BIRTHDAY; 115 case sync_pb::SyncEnums::THROTTLED: 116 return THROTTLED; 117 case sync_pb::SyncEnums::CLEAR_PENDING: 118 return CLEAR_PENDING; 119 case sync_pb::SyncEnums::TRANSIENT_ERROR: 120 return TRANSIENT_ERROR; 121 case sync_pb::SyncEnums::MIGRATION_DONE: 122 return MIGRATION_DONE; 123 case sync_pb::SyncEnums::DISABLED_BY_ADMIN: 124 return DISABLED_BY_ADMIN; 125 case sync_pb::SyncEnums::USER_ROLLBACK: 126 return USER_ROLLBACK; 127 case sync_pb::SyncEnums::UNKNOWN: 128 return UNKNOWN_ERROR; 129 case sync_pb::SyncEnums::USER_NOT_ACTIVATED: 130 case sync_pb::SyncEnums::AUTH_INVALID: 131 case sync_pb::SyncEnums::ACCESS_DENIED: 132 return INVALID_CREDENTIAL; 133 default: 134 NOTREACHED(); 135 return UNKNOWN_ERROR; 136 } 137 } 138 139 ClientAction ConvertClientActionPBToLocalClientAction( 140 const sync_pb::SyncEnums::Action& action) { 141 switch (action) { 142 case sync_pb::SyncEnums::UPGRADE_CLIENT: 143 return UPGRADE_CLIENT; 144 case sync_pb::SyncEnums::CLEAR_USER_DATA_AND_RESYNC: 145 return CLEAR_USER_DATA_AND_RESYNC; 146 case sync_pb::SyncEnums::ENABLE_SYNC_ON_ACCOUNT: 147 return ENABLE_SYNC_ON_ACCOUNT; 148 case sync_pb::SyncEnums::STOP_AND_RESTART_SYNC: 149 return STOP_AND_RESTART_SYNC; 150 case sync_pb::SyncEnums::DISABLE_SYNC_ON_CLIENT: 151 return DISABLE_SYNC_ON_CLIENT; 152 case sync_pb::SyncEnums::UNKNOWN_ACTION: 153 return UNKNOWN_ACTION; 154 default: 155 NOTREACHED(); 156 return UNKNOWN_ACTION; 157 } 158 } 159 160 } // namespace 161 162 ModelTypeSet GetTypesToMigrate(const ClientToServerResponse& response) { 163 ModelTypeSet to_migrate; 164 for (int i = 0; i < response.migrated_data_type_id_size(); i++) { 165 int field_number = response.migrated_data_type_id(i); 166 ModelType model_type = GetModelTypeFromSpecificsFieldNumber(field_number); 167 if (!IsRealDataType(model_type)) { 168 DLOG(WARNING) << "Unknown field number " << field_number; 169 continue; 170 } 171 to_migrate.Put(model_type); 172 } 173 return to_migrate; 174 } 175 176 SyncProtocolError ConvertErrorPBToLocalType( 177 const sync_pb::ClientToServerResponse_Error& error) { 178 SyncProtocolError sync_protocol_error; 179 sync_protocol_error.error_type = ConvertSyncProtocolErrorTypePBToLocalType( 180 error.error_type()); 181 sync_protocol_error.error_description = error.error_description(); 182 sync_protocol_error.url = error.url(); 183 sync_protocol_error.action = ConvertClientActionPBToLocalClientAction( 184 error.action()); 185 186 if (error.error_data_type_ids_size() > 0) { 187 // THROTTLED is currently the only error code that uses |error_data_types|. 188 DCHECK_EQ(error.error_type(), sync_pb::SyncEnums::THROTTLED); 189 for (int i = 0; i < error.error_data_type_ids_size(); ++i) { 190 int field_number = error.error_data_type_ids(i); 191 ModelType model_type = 192 GetModelTypeFromSpecificsFieldNumber(field_number); 193 if (!IsRealDataType(model_type)) { 194 DLOG(WARNING) << "Unknown field number " << field_number; 195 continue; 196 } 197 sync_protocol_error.error_data_types.Put(model_type); 198 } 199 } 200 201 return sync_protocol_error; 202 } 203 204 // static 205 bool SyncerProtoUtil::VerifyResponseBirthday( 206 const ClientToServerResponse& response, 207 syncable::Directory* dir) { 208 209 std::string local_birthday = dir->store_birthday(); 210 211 if (local_birthday.empty()) { 212 if (!response.has_store_birthday()) { 213 LOG(WARNING) << "Expected a birthday on first sync."; 214 return false; 215 } 216 217 DVLOG(1) << "New store birthday: " << response.store_birthday(); 218 dir->set_store_birthday(response.store_birthday()); 219 return true; 220 } 221 222 // Error situation, but we're not stuck. 223 if (!response.has_store_birthday()) { 224 LOG(WARNING) << "No birthday in server response?"; 225 return true; 226 } 227 228 if (response.store_birthday() != local_birthday) { 229 LOG(WARNING) << "Birthday changed, showing syncer stuck"; 230 return false; 231 } 232 233 return true; 234 } 235 236 // static 237 bool SyncerProtoUtil::IsSyncDisabledByAdmin( 238 const sync_pb::ClientToServerResponse& response) { 239 return (response.has_error_code() && 240 response.error_code() == sync_pb::SyncEnums::DISABLED_BY_ADMIN); 241 } 242 243 // static 244 void SyncerProtoUtil::AddRequestBirthday(syncable::Directory* dir, 245 ClientToServerMessage* msg) { 246 if (!dir->store_birthday().empty()) 247 msg->set_store_birthday(dir->store_birthday()); 248 } 249 250 // static 251 void SyncerProtoUtil::AddBagOfChips(syncable::Directory* dir, 252 ClientToServerMessage* msg) { 253 msg->mutable_bag_of_chips()->ParseFromString(dir->bag_of_chips()); 254 } 255 256 // static 257 void SyncerProtoUtil::SetProtocolVersion(ClientToServerMessage* msg) { 258 const int current_version = 259 ClientToServerMessage::default_instance().protocol_version(); 260 msg->set_protocol_version(current_version); 261 } 262 263 // static 264 bool SyncerProtoUtil::PostAndProcessHeaders(ServerConnectionManager* scm, 265 sessions::SyncSession* session, 266 const ClientToServerMessage& msg, 267 ClientToServerResponse* response) { 268 ServerConnectionManager::PostBufferParams params; 269 DCHECK(msg.has_protocol_version()); 270 DCHECK_EQ(msg.protocol_version(), 271 ClientToServerMessage::default_instance().protocol_version()); 272 msg.SerializeToString(¶ms.buffer_in); 273 274 ScopedServerStatusWatcher server_status_watcher(scm, ¶ms.response); 275 // Fills in params.buffer_out and params.response. 276 if (!scm->PostBufferWithCachedAuth(¶ms, &server_status_watcher)) { 277 LOG(WARNING) << "Error posting from syncer:" << params.response; 278 return false; 279 } 280 281 if (response->ParseFromString(params.buffer_out)) { 282 // TODO(tim): This is an egregious layering violation (bug 35060). 283 switch (response->error_code()) { 284 case sync_pb::SyncEnums::ACCESS_DENIED: 285 case sync_pb::SyncEnums::AUTH_INVALID: 286 case sync_pb::SyncEnums::USER_NOT_ACTIVATED: 287 // Fires on ScopedServerStatusWatcher 288 params.response.server_status = HttpResponse::SYNC_AUTH_ERROR; 289 return false; 290 default: 291 return true; 292 } 293 } 294 295 return false; 296 } 297 298 base::TimeDelta SyncerProtoUtil::GetThrottleDelay( 299 const ClientToServerResponse& response) { 300 base::TimeDelta throttle_delay = 301 base::TimeDelta::FromSeconds(kSyncDelayAfterThrottled); 302 if (response.has_client_command()) { 303 const sync_pb::ClientCommand& command = response.client_command(); 304 if (command.has_throttle_delay_seconds()) { 305 throttle_delay = 306 base::TimeDelta::FromSeconds(command.throttle_delay_seconds()); 307 } 308 } 309 return throttle_delay; 310 } 311 312 namespace { 313 314 // Helper function for an assertion in PostClientToServerMessage. 315 bool IsVeryFirstGetUpdates(const ClientToServerMessage& message) { 316 if (!message.has_get_updates()) 317 return false; 318 DCHECK_LT(0, message.get_updates().from_progress_marker_size()); 319 for (int i = 0; i < message.get_updates().from_progress_marker_size(); ++i) { 320 if (!message.get_updates().from_progress_marker(i).token().empty()) 321 return false; 322 } 323 return true; 324 } 325 326 // TODO(lipalani) : Rename these function names as per the CR for issue 7740067. 327 SyncProtocolError ConvertLegacyErrorCodeToNewError( 328 const sync_pb::SyncEnums::ErrorType& error_type) { 329 SyncProtocolError error; 330 error.error_type = ConvertSyncProtocolErrorTypePBToLocalType(error_type); 331 if (error_type == sync_pb::SyncEnums::CLEAR_PENDING || 332 error_type == sync_pb::SyncEnums::NOT_MY_BIRTHDAY) { 333 error.action = DISABLE_SYNC_ON_CLIENT; 334 } else if (error_type == sync_pb::SyncEnums::DISABLED_BY_ADMIN) { 335 error.action = STOP_SYNC_FOR_DISABLED_ACCOUNT; 336 } else if (error_type == sync_pb::SyncEnums::USER_ROLLBACK) { 337 error.action = DISABLE_SYNC_AND_ROLLBACK; 338 } // There is no other action we can compute for legacy server. 339 return error; 340 } 341 342 } // namespace 343 344 // static 345 SyncerError SyncerProtoUtil::PostClientToServerMessage( 346 ClientToServerMessage* msg, 347 ClientToServerResponse* response, 348 SyncSession* session) { 349 CHECK(response); 350 DCHECK(!msg->get_updates().has_from_timestamp()); // Deprecated. 351 DCHECK(!msg->get_updates().has_requested_types()); // Deprecated. 352 353 // Add must-have fields. 354 SetProtocolVersion(msg); 355 AddRequestBirthday(session->context()->directory(), msg); 356 DCHECK(msg->has_store_birthday() || IsVeryFirstGetUpdates(*msg)); 357 AddBagOfChips(session->context()->directory(), msg); 358 msg->set_api_key(google_apis::GetAPIKey()); 359 msg->mutable_client_status()->CopyFrom(session->context()->client_status()); 360 msg->set_invalidator_client_id(session->context()->invalidator_client_id()); 361 362 syncable::Directory* dir = session->context()->directory(); 363 364 LogClientToServerMessage(*msg); 365 if (!PostAndProcessHeaders(session->context()->connection_manager(), session, 366 *msg, response)) { 367 // There was an error establishing communication with the server. 368 // We can not proceed beyond this point. 369 const HttpResponse::ServerConnectionCode server_status = 370 session->context()->connection_manager()->server_status(); 371 372 DCHECK_NE(server_status, HttpResponse::NONE); 373 DCHECK_NE(server_status, HttpResponse::SERVER_CONNECTION_OK); 374 375 return ServerConnectionErrorAsSyncerError(server_status); 376 } 377 LogClientToServerResponse(*response); 378 379 // Persist a bag of chips if it has been sent by the server. 380 PersistBagOfChips(dir, *response); 381 382 SyncProtocolError sync_protocol_error; 383 384 // The DISABLED_BY_ADMIN error overrides other errors sent by the server. 385 if (IsSyncDisabledByAdmin(*response)) { 386 sync_protocol_error.error_type = DISABLED_BY_ADMIN; 387 sync_protocol_error.action = STOP_SYNC_FOR_DISABLED_ACCOUNT; 388 } else if (!VerifyResponseBirthday(*response, dir)) { 389 // If sync isn't disabled, first check for a birthday mismatch error. 390 sync_protocol_error.error_type = NOT_MY_BIRTHDAY; 391 sync_protocol_error.action = DISABLE_SYNC_ON_CLIENT; 392 } else if (response->has_error()) { 393 // This is a new server. Just get the error from the protocol. 394 sync_protocol_error = ConvertErrorPBToLocalType(response->error()); 395 } else { 396 // Legacy server implementation. Compute the error based on |error_code|. 397 sync_protocol_error = ConvertLegacyErrorCodeToNewError( 398 response->error_code()); 399 } 400 401 // Inform the delegate of the error we got. 402 session->delegate()->OnSyncProtocolError(sync_protocol_error); 403 404 // Update our state for any other commands we've received. 405 if (response->has_client_command()) { 406 const sync_pb::ClientCommand& command = response->client_command(); 407 if (command.has_max_commit_batch_size()) { 408 session->context()->set_max_commit_batch_size( 409 command.max_commit_batch_size()); 410 } 411 412 if (command.has_set_sync_long_poll_interval()) { 413 session->delegate()->OnReceivedLongPollIntervalUpdate( 414 base::TimeDelta::FromSeconds(command.set_sync_long_poll_interval())); 415 } 416 417 if (command.has_set_sync_poll_interval()) { 418 session->delegate()->OnReceivedShortPollIntervalUpdate( 419 base::TimeDelta::FromSeconds(command.set_sync_poll_interval())); 420 } 421 422 if (command.has_sessions_commit_delay_seconds()) { 423 std::map<ModelType, base::TimeDelta> delay_map; 424 delay_map[SESSIONS] = 425 base::TimeDelta::FromSeconds(command.sessions_commit_delay_seconds()); 426 session->delegate()->OnReceivedCustomNudgeDelays(delay_map); 427 } 428 429 if (command.has_client_invalidation_hint_buffer_size()) { 430 session->delegate()->OnReceivedClientInvalidationHintBufferSize( 431 command.client_invalidation_hint_buffer_size()); 432 } 433 434 if (command.has_gu_retry_delay_seconds()) { 435 session->delegate()->OnReceivedGuRetryDelay( 436 base::TimeDelta::FromSeconds(command.gu_retry_delay_seconds())); 437 } 438 439 if (command.custom_nudge_delays_size() > 0) { 440 // Note that because this happens after the sessions_commit_delay_seconds 441 // handling, any SESSIONS value in this map will override the one in 442 // sessions_commit_delay_seconds. 443 std::map<ModelType, base::TimeDelta> delay_map; 444 for (int i = 0; i < command.custom_nudge_delays_size(); ++i) { 445 ModelType type = GetModelTypeFromSpecificsFieldNumber( 446 command.custom_nudge_delays(i).datatype_id()); 447 if (ProtocolTypes().Has(type)) { 448 delay_map[type] = base::TimeDelta::FromMilliseconds( 449 command.custom_nudge_delays(i).delay_ms()); 450 } 451 } 452 session->delegate()->OnReceivedCustomNudgeDelays(delay_map); 453 } 454 } 455 456 // Now do any special handling for the error type and decide on the return 457 // value. 458 switch (sync_protocol_error.error_type) { 459 case UNKNOWN_ERROR: 460 LOG(WARNING) << "Sync protocol out-of-date. The server is using a more " 461 << "recent version."; 462 return SERVER_RETURN_UNKNOWN_ERROR; 463 case SYNC_SUCCESS: 464 LogResponseProfilingData(*response); 465 return SYNCER_OK; 466 case THROTTLED: 467 if (sync_protocol_error.error_data_types.Empty()) { 468 DLOG(WARNING) << "Client fully throttled by syncer."; 469 session->delegate()->OnThrottled(GetThrottleDelay(*response)); 470 } else { 471 DLOG(WARNING) << "Some types throttled by syncer."; 472 session->delegate()->OnTypesThrottled( 473 sync_protocol_error.error_data_types, 474 GetThrottleDelay(*response)); 475 } 476 return SERVER_RETURN_THROTTLED; 477 case TRANSIENT_ERROR: 478 return SERVER_RETURN_TRANSIENT_ERROR; 479 case MIGRATION_DONE: 480 LOG_IF(ERROR, 0 >= response->migrated_data_type_id_size()) 481 << "MIGRATION_DONE but no types specified."; 482 session->delegate()->OnReceivedMigrationRequest( 483 GetTypesToMigrate(*response)); 484 return SERVER_RETURN_MIGRATION_DONE; 485 case CLEAR_PENDING: 486 return SERVER_RETURN_CLEAR_PENDING; 487 case NOT_MY_BIRTHDAY: 488 return SERVER_RETURN_NOT_MY_BIRTHDAY; 489 case DISABLED_BY_ADMIN: 490 return SERVER_RETURN_DISABLED_BY_ADMIN; 491 case USER_ROLLBACK: 492 return SERVER_RETURN_USER_ROLLBACK; 493 default: 494 NOTREACHED(); 495 return UNSET; 496 } 497 } 498 499 // static 500 bool SyncerProtoUtil::ShouldMaintainPosition( 501 const sync_pb::SyncEntity& sync_entity) { 502 // Maintain positions for bookmarks that are not server-defined top-level 503 // folders. 504 return GetModelType(sync_entity) == BOOKMARKS 505 && !(sync_entity.folder() && 506 !sync_entity.server_defined_unique_tag().empty()); 507 } 508 509 // static 510 void SyncerProtoUtil::CopyProtoBytesIntoBlob(const std::string& proto_bytes, 511 syncable::Blob* blob) { 512 syncable::Blob proto_blob(proto_bytes.begin(), proto_bytes.end()); 513 blob->swap(proto_blob); 514 } 515 516 // static 517 bool SyncerProtoUtil::ProtoBytesEqualsBlob(const std::string& proto_bytes, 518 const syncable::Blob& blob) { 519 if (proto_bytes.size() != blob.size()) 520 return false; 521 return std::equal(proto_bytes.begin(), proto_bytes.end(), blob.begin()); 522 } 523 524 // static 525 void SyncerProtoUtil::CopyBlobIntoProtoBytes(const syncable::Blob& blob, 526 std::string* proto_bytes) { 527 std::string blob_string(blob.begin(), blob.end()); 528 proto_bytes->swap(blob_string); 529 } 530 531 // static 532 const std::string& SyncerProtoUtil::NameFromSyncEntity( 533 const sync_pb::SyncEntity& entry) { 534 if (entry.has_non_unique_name()) 535 return entry.non_unique_name(); 536 return entry.name(); 537 } 538 539 // static 540 const std::string& SyncerProtoUtil::NameFromCommitEntryResponse( 541 const sync_pb::CommitResponse_EntryResponse& entry) { 542 if (entry.has_non_unique_name()) 543 return entry.non_unique_name(); 544 return entry.name(); 545 } 546 547 // static 548 void SyncerProtoUtil::PersistBagOfChips(syncable::Directory* dir, 549 const sync_pb::ClientToServerResponse& response) { 550 if (!response.has_new_bag_of_chips()) 551 return; 552 std::string bag_of_chips; 553 if (response.new_bag_of_chips().SerializeToString(&bag_of_chips)) 554 dir->set_bag_of_chips(bag_of_chips); 555 } 556 557 std::string SyncerProtoUtil::SyncEntityDebugString( 558 const sync_pb::SyncEntity& entry) { 559 const std::string& mtime_str = 560 GetTimeDebugString(ProtoTimeToTime(entry.mtime())); 561 const std::string& ctime_str = 562 GetTimeDebugString(ProtoTimeToTime(entry.ctime())); 563 return base::StringPrintf( 564 "id: %s, parent_id: %s, " 565 "version: %" PRId64"d, " 566 "mtime: %" PRId64"d (%s), " 567 "ctime: %" PRId64"d (%s), " 568 "name: %s, sync_timestamp: %" PRId64"d, " 569 "%s ", 570 entry.id_string().c_str(), 571 entry.parent_id_string().c_str(), 572 entry.version(), 573 entry.mtime(), mtime_str.c_str(), 574 entry.ctime(), ctime_str.c_str(), 575 entry.name().c_str(), entry.sync_timestamp(), 576 entry.deleted() ? "deleted, ":""); 577 } 578 579 namespace { 580 std::string GetUpdatesResponseString( 581 const sync_pb::GetUpdatesResponse& response) { 582 std::string output; 583 output.append("GetUpdatesResponse:\n"); 584 for (int i = 0; i < response.entries_size(); i++) { 585 output.append(SyncerProtoUtil::SyncEntityDebugString(response.entries(i))); 586 output.append("\n"); 587 } 588 return output; 589 } 590 } // namespace 591 592 std::string SyncerProtoUtil::ClientToServerResponseDebugString( 593 const ClientToServerResponse& response) { 594 // Add more handlers as needed. 595 std::string output; 596 if (response.has_get_updates()) 597 output.append(GetUpdatesResponseString(response.get_updates())); 598 return output; 599 } 600 601 } // namespace syncer 602