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(¶ms, &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