// Copyright (c) 2010 The Chromium Authors. All rights reserved. // Use of this source code is governed by a BSD-style license that can be // found in the LICENSE file. #include "chrome/browser/sync/engine/syncer_proto_util.h" #include "base/format_macros.h" #include "base/string_util.h" #include "chrome/browser/sync/engine/net/server_connection_manager.h" #include "chrome/browser/sync/engine/syncer.h" #include "chrome/browser/sync/engine/syncer_types.h" #include "chrome/browser/sync/engine/syncer_util.h" #include "chrome/browser/sync/protocol/service_constants.h" #include "chrome/browser/sync/sessions/sync_session.h" #include "chrome/browser/sync/syncable/directory_manager.h" #include "chrome/browser/sync/syncable/model_type.h" #include "chrome/browser/sync/syncable/syncable-inl.h" #include "chrome/browser/sync/syncable/syncable.h" using std::string; using std::stringstream; using syncable::BASE_VERSION; using syncable::CTIME; using syncable::ID; using syncable::IS_DEL; using syncable::IS_DIR; using syncable::IS_UNSYNCED; using syncable::MTIME; using syncable::PARENT_ID; using syncable::ScopedDirLookup; using syncable::SyncName; namespace browser_sync { using sessions::SyncSession; namespace { // Time to backoff syncing after receiving a throttled response. static const int kSyncDelayAfterThrottled = 2 * 60 * 60; // 2 hours void LogResponseProfilingData(const ClientToServerResponse& response) { if (response.has_profiling_data()) { stringstream response_trace; response_trace << "Server response trace:"; if (response.profiling_data().has_user_lookup_time()) { response_trace << " user lookup: " << response.profiling_data().user_lookup_time() << "ms"; } if (response.profiling_data().has_meta_data_write_time()) { response_trace << " meta write: " << response.profiling_data().meta_data_write_time() << "ms"; } if (response.profiling_data().has_meta_data_read_time()) { response_trace << " meta read: " << response.profiling_data().meta_data_read_time() << "ms"; } if (response.profiling_data().has_file_data_write_time()) { response_trace << " file write: " << response.profiling_data().file_data_write_time() << "ms"; } if (response.profiling_data().has_file_data_read_time()) { response_trace << " file read: " << response.profiling_data().file_data_read_time() << "ms"; } if (response.profiling_data().has_total_request_time()) { response_trace << " total time: " << response.profiling_data().total_request_time() << "ms"; } VLOG(1) << response_trace.str(); } } } // namespace // static void SyncerProtoUtil::HandleMigrationDoneResponse( const sync_pb::ClientToServerResponse* response, sessions::SyncSession* session) { LOG_IF(ERROR, 0 >= response->migrated_data_type_id_size()) << "MIGRATION_DONE but no types specified."; syncable::ModelTypeSet to_migrate; for (int i = 0; i < response->migrated_data_type_id_size(); i++) { to_migrate.insert(syncable::GetModelTypeFromExtensionFieldNumber( response->migrated_data_type_id(i))); } session->status_controller()->set_types_needing_local_migration(to_migrate); } // static bool SyncerProtoUtil::VerifyResponseBirthday(syncable::Directory* dir, const ClientToServerResponse* response) { std::string local_birthday = dir->store_birthday(); if (response->error_code() == ClientToServerResponse::CLEAR_PENDING) { // Birthday verification failures result in stopping sync and deleting // local sync data. return false; } if (local_birthday.empty()) { if (!response->has_store_birthday()) { LOG(WARNING) << "Expected a birthday on first sync."; return false; } VLOG(1) << "New store birthday: " << response->store_birthday(); dir->set_store_birthday(response->store_birthday()); return true; } // Error situation, but we're not stuck. if (!response->has_store_birthday()) { LOG(WARNING) << "No birthday in server response?"; return true; } if (response->store_birthday() != local_birthday) { LOG(WARNING) << "Birthday changed, showing syncer stuck"; return false; } return true; } // static void SyncerProtoUtil::AddRequestBirthday(syncable::Directory* dir, ClientToServerMessage* msg) { if (!dir->store_birthday().empty()) msg->set_store_birthday(dir->store_birthday()); } // static bool SyncerProtoUtil::PostAndProcessHeaders(ServerConnectionManager* scm, sessions::SyncSession* session, const ClientToServerMessage& msg, ClientToServerResponse* response) { std::string tx, rx; msg.SerializeToString(&tx); HttpResponse http_response; ServerConnectionManager::PostBufferParams params = { tx, &rx, &http_response }; ScopedServerStatusWatcher server_status_watcher(scm, &http_response); if (!scm->PostBufferWithCachedAuth(¶ms, &server_status_watcher)) { LOG(WARNING) << "Error posting from syncer:" << http_response; return false; } std::string new_token = http_response.update_client_auth_header; if (!new_token.empty()) { SyncEngineEvent event(SyncEngineEvent::UPDATED_TOKEN); event.updated_token = new_token; session->context()->NotifyListeners(event); } if (response->ParseFromString(rx)) { // TODO(tim): This is an egregious layering violation (bug 35060). switch (response->error_code()) { case ClientToServerResponse::ACCESS_DENIED: case ClientToServerResponse::AUTH_INVALID: case ClientToServerResponse::USER_NOT_ACTIVATED: // Fires on ScopedServerStatusWatcher http_response.server_status = HttpResponse::SYNC_AUTH_ERROR; return false; default: return true; } } return false; } namespace { // Helper function for an assertion in PostClientToServerMessage. bool IsVeryFirstGetUpdates(const ClientToServerMessage& message) { if (!message.has_get_updates()) return false; DCHECK_LT(0, message.get_updates().from_progress_marker_size()); for (int i = 0; i < message.get_updates().from_progress_marker_size(); ++i) { if (!message.get_updates().from_progress_marker(i).token().empty()) return false; } return true; } } // namespace // static bool SyncerProtoUtil::PostClientToServerMessage( const ClientToServerMessage& msg, ClientToServerResponse* response, SyncSession* session) { CHECK(response); DCHECK(!msg.get_updates().has_from_timestamp()); // Deprecated. DCHECK(!msg.get_updates().has_requested_types()); // Deprecated. DCHECK(msg.has_store_birthday() || IsVeryFirstGetUpdates(msg)) << "Must call AddRequestBirthday to set birthday."; ScopedDirLookup dir(session->context()->directory_manager(), session->context()->account_name()); if (!dir.good()) return false; if (!PostAndProcessHeaders(session->context()->connection_manager(), session, msg, response)) return false; if (!VerifyResponseBirthday(dir, response)) { session->status_controller()->set_syncer_stuck(true); session->delegate()->OnShouldStopSyncingPermanently(); return false; } switch (response->error_code()) { case ClientToServerResponse::UNKNOWN: LOG(WARNING) << "Sync protocol out-of-date. The server is using a more " << "recent version."; return false; case ClientToServerResponse::SUCCESS: LogResponseProfilingData(*response); return true; case ClientToServerResponse::THROTTLED: LOG(WARNING) << "Client silenced by server."; session->delegate()->OnSilencedUntil(base::TimeTicks::Now() + base::TimeDelta::FromSeconds(kSyncDelayAfterThrottled)); return false; case ClientToServerResponse::TRANSIENT_ERROR: return false; case ClientToServerResponse::MIGRATION_DONE: HandleMigrationDoneResponse(response, session); return false; case ClientToServerResponse::USER_NOT_ACTIVATED: case ClientToServerResponse::AUTH_INVALID: case ClientToServerResponse::ACCESS_DENIED: // WARNING: PostAndProcessHeaders contains a hack for this case. LOG(WARNING) << "SyncerProtoUtil: Authentication expired."; // TODO(sync): Was this meant to be a fall-through? default: NOTREACHED(); return false; } } // static bool SyncerProtoUtil::Compare(const syncable::Entry& local_entry, const SyncEntity& server_entry) { const std::string name = NameFromSyncEntity(server_entry); CHECK(local_entry.Get(ID) == server_entry.id()) << " SyncerProtoUtil::Compare precondition not met."; CHECK(server_entry.version() == local_entry.Get(BASE_VERSION)) << " SyncerProtoUtil::Compare precondition not met."; CHECK(!local_entry.Get(IS_UNSYNCED)) << " SyncerProtoUtil::Compare precondition not met."; if (local_entry.Get(IS_DEL) && server_entry.deleted()) return true; if (!ClientAndServerTimeMatch(local_entry.Get(CTIME), server_entry.ctime())) { LOG(WARNING) << "ctime mismatch"; return false; } // These checks are somewhat prolix, but they're easier to debug than a big // boolean statement. string client_name = local_entry.Get(syncable::NON_UNIQUE_NAME); if (client_name != name) { LOG(WARNING) << "Client name mismatch"; return false; } if (local_entry.Get(PARENT_ID) != server_entry.parent_id()) { LOG(WARNING) << "Parent ID mismatch"; return false; } if (local_entry.Get(IS_DIR) != server_entry.IsFolder()) { LOG(WARNING) << "Dir field mismatch"; return false; } if (local_entry.Get(IS_DEL) != server_entry.deleted()) { LOG(WARNING) << "Deletion mismatch"; return false; } if (!local_entry.Get(IS_DIR) && !ClientAndServerTimeMatch(local_entry.Get(MTIME), server_entry.mtime())) { LOG(WARNING) << "mtime mismatch"; return false; } return true; } // static void SyncerProtoUtil::CopyProtoBytesIntoBlob(const std::string& proto_bytes, syncable::Blob* blob) { syncable::Blob proto_blob(proto_bytes.begin(), proto_bytes.end()); blob->swap(proto_blob); } // static bool SyncerProtoUtil::ProtoBytesEqualsBlob(const std::string& proto_bytes, const syncable::Blob& blob) { if (proto_bytes.size() != blob.size()) return false; return std::equal(proto_bytes.begin(), proto_bytes.end(), blob.begin()); } // static void SyncerProtoUtil::CopyBlobIntoProtoBytes(const syncable::Blob& blob, std::string* proto_bytes) { std::string blob_string(blob.begin(), blob.end()); proto_bytes->swap(blob_string); } // static const std::string& SyncerProtoUtil::NameFromSyncEntity( const sync_pb::SyncEntity& entry) { if (entry.has_non_unique_name()) return entry.non_unique_name(); return entry.name(); } // static const std::string& SyncerProtoUtil::NameFromCommitEntryResponse( const CommitResponse_EntryResponse& entry) { if (entry.has_non_unique_name()) return entry.non_unique_name(); return entry.name(); } std::string SyncerProtoUtil::SyncEntityDebugString( const sync_pb::SyncEntity& entry) { return StringPrintf("id: %s, parent_id: %s, " "version: %"PRId64"d, " "mtime: %" PRId64"d (client: %" PRId64"d), " "ctime: %" PRId64"d (client: %" PRId64"d), " "name: %s, sync_timestamp: %" PRId64"d, " "%s ", entry.id_string().c_str(), entry.parent_id_string().c_str(), entry.version(), entry.mtime(), ServerTimeToClientTime(entry.mtime()), entry.ctime(), ServerTimeToClientTime(entry.ctime()), entry.name().c_str(), entry.sync_timestamp(), entry.deleted() ? "deleted, ":""); } namespace { std::string GetUpdatesResponseString( const sync_pb::GetUpdatesResponse& response) { std::string output; output.append("GetUpdatesResponse:\n"); for (int i = 0; i < response.entries_size(); i++) { output.append(SyncerProtoUtil::SyncEntityDebugString(response.entries(i))); output.append("\n"); } return output; } } // namespace std::string SyncerProtoUtil::ClientToServerResponseDebugString( const sync_pb::ClientToServerResponse& response) { // Add more handlers as needed. std::string output; if (response.has_get_updates()) output.append(GetUpdatesResponseString(response.get_updates())); return output; } } // namespace browser_sync