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
LogResponseProfilingData(const ClientToServerResponse & response)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
HandleMigrationDoneResponse(const sync_pb::ClientToServerResponse * response,sessions::SyncSession * session)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
VerifyResponseBirthday(syncable::Directory * dir,const ClientToServerResponse * response)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
AddRequestBirthday(syncable::Directory * dir,ClientToServerMessage * msg)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
PostAndProcessHeaders(ServerConnectionManager * scm,sessions::SyncSession * session,const ClientToServerMessage & msg,ClientToServerResponse * response)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.
IsVeryFirstGetUpdates(const ClientToServerMessage & message)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
PostClientToServerMessage(const ClientToServerMessage & msg,ClientToServerResponse * response,SyncSession * session)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
Compare(const syncable::Entry & local_entry,const SyncEntity & server_entry)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
CopyProtoBytesIntoBlob(const std::string & proto_bytes,syncable::Blob * blob)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
ProtoBytesEqualsBlob(const std::string & proto_bytes,const syncable::Blob & blob)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
CopyBlobIntoProtoBytes(const syncable::Blob & blob,std::string * proto_bytes)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
NameFromSyncEntity(const sync_pb::SyncEntity & entry)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
NameFromCommitEntryResponse(const CommitResponse_EntryResponse & entry)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
SyncEntityDebugString(const sync_pb::SyncEntity & entry)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 {
GetUpdatesResponseString(const sync_pb::GetUpdatesResponse & response)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
ClientToServerResponseDebugString(const sync_pb::ClientToServerResponse & response)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