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/process_commit_response_command.h"
6
7 #include <set>
8 #include <string>
9 #include <vector>
10
11 #include "base/basictypes.h"
12 #include "chrome/browser/sync/engine/syncer_proto_util.h"
13 #include "chrome/browser/sync/engine/syncer_util.h"
14 #include "chrome/browser/sync/engine/syncproto.h"
15 #include "chrome/browser/sync/sessions/sync_session.h"
16 #include "chrome/browser/sync/syncable/directory_manager.h"
17 #include "chrome/browser/sync/syncable/syncable.h"
18
19 using syncable::ScopedDirLookup;
20 using syncable::WriteTransaction;
21 using syncable::MutableEntry;
22 using syncable::Entry;
23
24 using std::set;
25 using std::string;
26 using std::vector;
27
28 using syncable::BASE_VERSION;
29 using syncable::GET_BY_ID;
30 using syncable::ID;
31 using syncable::IS_DEL;
32 using syncable::IS_DIR;
33 using syncable::IS_UNAPPLIED_UPDATE;
34 using syncable::IS_UNSYNCED;
35 using syncable::PARENT_ID;
36 using syncable::SERVER_IS_DEL;
37 using syncable::SERVER_PARENT_ID;
38 using syncable::SERVER_POSITION_IN_PARENT;
39 using syncable::SERVER_VERSION;
40 using syncable::SYNCER;
41 using syncable::SYNCING;
42
43 namespace browser_sync {
44
45 using sessions::OrderedCommitSet;
46 using sessions::StatusController;
47 using sessions::SyncSession;
48 using sessions::ConflictProgress;
49
IncrementErrorCounters(StatusController * status)50 void IncrementErrorCounters(StatusController* status) {
51 status->increment_num_consecutive_errors();
52 }
ResetErrorCounters(StatusController * status)53 void ResetErrorCounters(StatusController* status) {
54 status->set_num_consecutive_errors(0);
55 }
56
ProcessCommitResponseCommand()57 ProcessCommitResponseCommand::ProcessCommitResponseCommand() {}
~ProcessCommitResponseCommand()58 ProcessCommitResponseCommand::~ProcessCommitResponseCommand() {}
59
ModelNeutralExecuteImpl(sessions::SyncSession * session)60 bool ProcessCommitResponseCommand::ModelNeutralExecuteImpl(
61 sessions::SyncSession* session) {
62 ScopedDirLookup dir(session->context()->directory_manager(),
63 session->context()->account_name());
64 if (!dir.good()) {
65 LOG(ERROR) << "Scoped dir lookup failed!";
66 return false;
67 }
68
69 StatusController* status = session->status_controller();
70 const ClientToServerResponse& response(status->commit_response());
71 const vector<syncable::Id>& commit_ids(status->commit_ids());
72
73 if (!response.has_commit()) {
74 // TODO(sync): What if we didn't try to commit anything?
75 LOG(WARNING) << "Commit response has no commit body!";
76 IncrementErrorCounters(status);
77 return false;
78 }
79
80 const CommitResponse& cr = response.commit();
81 int commit_count = commit_ids.size();
82 if (cr.entryresponse_size() != commit_count) {
83 LOG(ERROR) << "Commit response has wrong number of entries! Expected:" <<
84 commit_count << " Got:" << cr.entryresponse_size();
85 for (int i = 0 ; i < cr.entryresponse_size() ; i++) {
86 LOG(ERROR) << "Response #" << i << " Value: " <<
87 cr.entryresponse(i).response_type();
88 if (cr.entryresponse(i).has_error_message())
89 LOG(ERROR) << " " << cr.entryresponse(i).error_message();
90 }
91 IncrementErrorCounters(status);
92 return false;
93 }
94 return true;
95 }
96
ModelChangingExecuteImpl(SyncSession * session)97 void ProcessCommitResponseCommand::ModelChangingExecuteImpl(
98 SyncSession* session) {
99 ProcessCommitResponse(session);
100 ExtensionsActivityMonitor* monitor = session->context()->extensions_monitor();
101 if (session->status_controller()->HasBookmarkCommitActivity() &&
102 session->status_controller()->syncer_status()
103 .num_successful_bookmark_commits == 0) {
104 monitor->PutRecords(session->extensions_activity());
105 session->mutable_extensions_activity()->clear();
106 }
107 }
108
ProcessCommitResponse(SyncSession * session)109 void ProcessCommitResponseCommand::ProcessCommitResponse(
110 SyncSession* session) {
111 // TODO(sync): This function returns if it sees problems. We probably want
112 // to flag the need for an update or similar.
113 ScopedDirLookup dir(session->context()->directory_manager(),
114 session->context()->account_name());
115 if (!dir.good()) {
116 LOG(ERROR) << "Scoped dir lookup failed!";
117 return;
118 }
119
120 StatusController* status = session->status_controller();
121 const ClientToServerResponse& response(status->commit_response());
122 const CommitResponse& cr = response.commit();
123 const sync_pb::CommitMessage& commit_message =
124 status->commit_message().commit();
125
126 // If we try to commit a parent and child together and the parent conflicts
127 // the child will have a bad parent causing an error. As this is not a
128 // critical error, we trap it and don't LOG(ERROR). To enable this we keep
129 // a map of conflicting new folders.
130 int transient_error_commits = 0;
131 int conflicting_commits = 0;
132 int error_commits = 0;
133 int successes = 0;
134 set<syncable::Id> conflicting_new_folder_ids;
135 set<syncable::Id> deleted_folders;
136 ConflictProgress* conflict_progress = status->mutable_conflict_progress();
137 OrderedCommitSet::Projection proj = status->commit_id_projection();
138 if (!proj.empty()) { // Scope for WriteTransaction.
139 WriteTransaction trans(dir, SYNCER, __FILE__, __LINE__);
140 for (size_t i = 0; i < proj.size(); i++) {
141 CommitResponse::ResponseType response_type =
142 ProcessSingleCommitResponse(&trans, cr.entryresponse(proj[i]),
143 commit_message.entries(proj[i]),
144 status->GetCommitIdAt(proj[i]),
145 &conflicting_new_folder_ids,
146 &deleted_folders);
147 switch (response_type) {
148 case CommitResponse::INVALID_MESSAGE:
149 ++error_commits;
150 break;
151 case CommitResponse::CONFLICT:
152 ++conflicting_commits;
153 // Only server CONFLICT responses will activate conflict resolution.
154 conflict_progress->AddConflictingItemById(
155 status->GetCommitIdAt(proj[i]));
156 break;
157 case CommitResponse::SUCCESS:
158 // TODO(sync): worry about sync_rate_ rate calc?
159 ++successes;
160 if (status->GetCommitIdModelTypeAt(proj[i]) == syncable::BOOKMARKS)
161 status->increment_num_successful_bookmark_commits();
162 status->increment_num_successful_commits();
163 break;
164 case CommitResponse::OVER_QUOTA:
165 // We handle over quota like a retry, which is same as transient.
166 case CommitResponse::RETRY:
167 case CommitResponse::TRANSIENT_ERROR:
168 // TODO(tim): Now that we have SyncSession::Delegate, we
169 // should plumb this directly for exponential backoff purposes rather
170 // than trying to infer from HasMoreToSync(). See
171 // SyncerThread::CalculatePollingWaitTime.
172 ++transient_error_commits;
173 break;
174 default:
175 LOG(FATAL) << "Bad return from ProcessSingleCommitResponse";
176 }
177 }
178 }
179
180 // TODO(sync): move status reporting elsewhere.
181 status->increment_num_conflicting_commits_by(conflicting_commits);
182 if (0 == successes) {
183 status->increment_num_consecutive_transient_error_commits_by(
184 transient_error_commits);
185 status->increment_num_consecutive_errors_by(transient_error_commits);
186 } else {
187 status->set_num_consecutive_transient_error_commits(0);
188 status->set_num_consecutive_errors(0);
189 }
190 int commit_count = static_cast<int>(proj.size());
191 if (commit_count != (conflicting_commits + error_commits +
192 transient_error_commits)) {
193 ResetErrorCounters(status);
194 }
195 SyncerUtil::MarkDeletedChildrenSynced(dir, &deleted_folders);
196
197 return;
198 }
199
LogServerError(const CommitResponse_EntryResponse & res)200 void LogServerError(const CommitResponse_EntryResponse& res) {
201 if (res.has_error_message())
202 LOG(WARNING) << " " << res.error_message();
203 else
204 LOG(WARNING) << " No detailed error message returned from server";
205 }
206
207 CommitResponse::ResponseType
ProcessSingleCommitResponse(syncable::WriteTransaction * trans,const sync_pb::CommitResponse_EntryResponse & pb_server_entry,const sync_pb::SyncEntity & commit_request_entry,const syncable::Id & pre_commit_id,std::set<syncable::Id> * conflicting_new_folder_ids,set<syncable::Id> * deleted_folders)208 ProcessCommitResponseCommand::ProcessSingleCommitResponse(
209 syncable::WriteTransaction* trans,
210 const sync_pb::CommitResponse_EntryResponse& pb_server_entry,
211 const sync_pb::SyncEntity& commit_request_entry,
212 const syncable::Id& pre_commit_id,
213 std::set<syncable::Id>* conflicting_new_folder_ids,
214 set<syncable::Id>* deleted_folders) {
215
216 const CommitResponse_EntryResponse& server_entry =
217 *static_cast<const CommitResponse_EntryResponse*>(&pb_server_entry);
218 MutableEntry local_entry(trans, GET_BY_ID, pre_commit_id);
219 CHECK(local_entry.good());
220 bool syncing_was_set = local_entry.Get(SYNCING);
221 local_entry.Put(SYNCING, false);
222
223 CommitResponse::ResponseType response = (CommitResponse::ResponseType)
224 server_entry.response_type();
225 if (!CommitResponse::ResponseType_IsValid(response)) {
226 LOG(ERROR) << "Commit response has unknown response type! Possibly out "
227 "of date client?";
228 return CommitResponse::INVALID_MESSAGE;
229 }
230 if (CommitResponse::TRANSIENT_ERROR == response) {
231 VLOG(1) << "Transient Error Committing: " << local_entry;
232 LogServerError(server_entry);
233 return CommitResponse::TRANSIENT_ERROR;
234 }
235 if (CommitResponse::INVALID_MESSAGE == response) {
236 LOG(ERROR) << "Error Commiting: " << local_entry;
237 LogServerError(server_entry);
238 return response;
239 }
240 if (CommitResponse::CONFLICT == response) {
241 VLOG(1) << "Conflict Committing: " << local_entry;
242 // TODO(nick): conflicting_new_folder_ids is a purposeless anachronism.
243 if (!pre_commit_id.ServerKnows() && local_entry.Get(IS_DIR)) {
244 conflicting_new_folder_ids->insert(pre_commit_id);
245 }
246 return response;
247 }
248 if (CommitResponse::RETRY == response) {
249 VLOG(1) << "Retry Committing: " << local_entry;
250 return response;
251 }
252 if (CommitResponse::OVER_QUOTA == response) {
253 LOG(WARNING) << "Hit deprecated OVER_QUOTA Committing: " << local_entry;
254 return response;
255 }
256 if (!server_entry.has_id_string()) {
257 LOG(ERROR) << "Commit response has no id";
258 return CommitResponse::INVALID_MESSAGE;
259 }
260
261 // Implied by the IsValid call above, but here for clarity.
262 DCHECK_EQ(CommitResponse::SUCCESS, response) << response;
263 // Check to see if we've been given the ID of an existing entry. If so treat
264 // it as an error response and retry later.
265 if (pre_commit_id != server_entry.id()) {
266 Entry e(trans, GET_BY_ID, server_entry.id());
267 if (e.good()) {
268 LOG(ERROR) << "Got duplicate id when commiting id: " << pre_commit_id <<
269 ". Treating as an error return";
270 return CommitResponse::INVALID_MESSAGE;
271 }
272 }
273
274 if (server_entry.version() == 0) {
275 LOG(WARNING) << "Server returned a zero version on a commit response.";
276 }
277
278 ProcessSuccessfulCommitResponse(commit_request_entry, server_entry,
279 pre_commit_id, &local_entry, syncing_was_set, deleted_folders);
280 return response;
281 }
282
GetResultingPostCommitName(const sync_pb::SyncEntity & committed_entry,const CommitResponse_EntryResponse & entry_response)283 const string& ProcessCommitResponseCommand::GetResultingPostCommitName(
284 const sync_pb::SyncEntity& committed_entry,
285 const CommitResponse_EntryResponse& entry_response) {
286 const string& response_name =
287 SyncerProtoUtil::NameFromCommitEntryResponse(entry_response);
288 if (!response_name.empty())
289 return response_name;
290 return SyncerProtoUtil::NameFromSyncEntity(committed_entry);
291 }
292
UpdateVersionAfterCommit(const sync_pb::SyncEntity & committed_entry,const CommitResponse_EntryResponse & entry_response,const syncable::Id & pre_commit_id,syncable::MutableEntry * local_entry)293 bool ProcessCommitResponseCommand::UpdateVersionAfterCommit(
294 const sync_pb::SyncEntity& committed_entry,
295 const CommitResponse_EntryResponse& entry_response,
296 const syncable::Id& pre_commit_id,
297 syncable::MutableEntry* local_entry) {
298 int64 old_version = local_entry->Get(BASE_VERSION);
299 int64 new_version = entry_response.version();
300 bool bad_commit_version = false;
301 if (committed_entry.deleted() &&
302 !local_entry->Get(syncable::UNIQUE_CLIENT_TAG).empty()) {
303 // If the item was deleted, and it's undeletable (uses the client tag),
304 // change the version back to zero. We must set the version to zero so
305 // that the server knows to re-create the item if it gets committed
306 // later for undeletion.
307 new_version = 0;
308 } else if (!pre_commit_id.ServerKnows()) {
309 bad_commit_version = 0 == new_version;
310 } else {
311 bad_commit_version = old_version > new_version;
312 }
313 if (bad_commit_version) {
314 LOG(ERROR) << "Bad version in commit return for " << *local_entry
315 << " new_id:" << entry_response.id() << " new_version:"
316 << entry_response.version();
317 return false;
318 }
319
320 // Update the base version and server version. The base version must change
321 // here, even if syncing_was_set is false; that's because local changes were
322 // on top of the successfully committed version.
323 local_entry->Put(BASE_VERSION, new_version);
324 VLOG(1) << "Commit is changing base version of " << local_entry->Get(ID)
325 << " to: " << new_version;
326 local_entry->Put(SERVER_VERSION, new_version);
327 return true;
328 }
329
ChangeIdAfterCommit(const CommitResponse_EntryResponse & entry_response,const syncable::Id & pre_commit_id,syncable::MutableEntry * local_entry)330 bool ProcessCommitResponseCommand::ChangeIdAfterCommit(
331 const CommitResponse_EntryResponse& entry_response,
332 const syncable::Id& pre_commit_id,
333 syncable::MutableEntry* local_entry) {
334 syncable::WriteTransaction* trans = local_entry->write_transaction();
335 if (entry_response.id() != pre_commit_id) {
336 if (pre_commit_id.ServerKnows()) {
337 // The server can sometimes generate a new ID on commit; for example,
338 // when committing an undeletion.
339 VLOG(1) << " ID changed while committing an old entry. "
340 << pre_commit_id << " became " << entry_response.id() << ".";
341 }
342 MutableEntry same_id(trans, GET_BY_ID, entry_response.id());
343 // We should trap this before this function.
344 if (same_id.good()) {
345 LOG(ERROR) << "ID clash with id " << entry_response.id()
346 << " during commit " << same_id;
347 return false;
348 }
349 SyncerUtil::ChangeEntryIDAndUpdateChildren(
350 trans, local_entry, entry_response.id());
351 VLOG(1) << "Changing ID to " << entry_response.id();
352 }
353 return true;
354 }
355
UpdateServerFieldsAfterCommit(const sync_pb::SyncEntity & committed_entry,const CommitResponse_EntryResponse & entry_response,syncable::MutableEntry * local_entry)356 void ProcessCommitResponseCommand::UpdateServerFieldsAfterCommit(
357 const sync_pb::SyncEntity& committed_entry,
358 const CommitResponse_EntryResponse& entry_response,
359 syncable::MutableEntry* local_entry) {
360
361 // We just committed an entry successfully, and now we want to make our view
362 // of the server state consistent with the server state. We must be careful;
363 // |entry_response| and |committed_entry| have some identically named
364 // fields. We only want to consider fields from |committed_entry| when there
365 // is not an overriding field in the |entry_response|. We do not want to
366 // update the server data from the local data in the entry -- it's possible
367 // that the local data changed during the commit, and even if not, the server
368 // has the last word on the values of several properties.
369
370 local_entry->Put(SERVER_IS_DEL, committed_entry.deleted());
371 if (committed_entry.deleted()) {
372 // Don't clobber any other fields of deleted objects.
373 return;
374 }
375
376 local_entry->Put(syncable::SERVER_IS_DIR,
377 (committed_entry.folder() ||
378 committed_entry.bookmarkdata().bookmark_folder()));
379 local_entry->Put(syncable::SERVER_SPECIFICS,
380 committed_entry.specifics());
381 local_entry->Put(syncable::SERVER_MTIME,
382 committed_entry.mtime());
383 local_entry->Put(syncable::SERVER_CTIME,
384 committed_entry.ctime());
385 local_entry->Put(syncable::SERVER_POSITION_IN_PARENT,
386 entry_response.position_in_parent());
387 // TODO(nick): The server doesn't set entry_response.server_parent_id in
388 // practice; to update SERVER_PARENT_ID appropriately here we'd need to
389 // get the post-commit ID of the parent indicated by
390 // committed_entry.parent_id_string(). That should be inferrable from the
391 // information we have, but it's a bit convoluted to pull it out directly.
392 // Getting this right is important: SERVER_PARENT_ID gets fed back into
393 // old_parent_id during the next commit.
394 local_entry->Put(syncable::SERVER_PARENT_ID,
395 local_entry->Get(syncable::PARENT_ID));
396 local_entry->Put(syncable::SERVER_NON_UNIQUE_NAME,
397 GetResultingPostCommitName(committed_entry, entry_response));
398
399 if (local_entry->Get(IS_UNAPPLIED_UPDATE)) {
400 // This shouldn't happen; an unapplied update shouldn't be committed, and
401 // if it were, the commit should have failed. But if it does happen: we've
402 // just overwritten the update info, so clear the flag.
403 local_entry->Put(IS_UNAPPLIED_UPDATE, false);
404 }
405 }
406
OverrideClientFieldsAfterCommit(const sync_pb::SyncEntity & committed_entry,const CommitResponse_EntryResponse & entry_response,syncable::MutableEntry * local_entry)407 void ProcessCommitResponseCommand::OverrideClientFieldsAfterCommit(
408 const sync_pb::SyncEntity& committed_entry,
409 const CommitResponse_EntryResponse& entry_response,
410 syncable::MutableEntry* local_entry) {
411 if (committed_entry.deleted()) {
412 // If an entry's been deleted, nothing else matters.
413 DCHECK(local_entry->Get(IS_DEL));
414 return;
415 }
416
417 // Update the name.
418 const string& server_name =
419 GetResultingPostCommitName(committed_entry, entry_response);
420 const string& old_name =
421 local_entry->Get(syncable::NON_UNIQUE_NAME);
422
423 if (!server_name.empty() && old_name != server_name) {
424 VLOG(1) << "During commit, server changed name: " << old_name
425 << " to new name: " << server_name;
426 local_entry->Put(syncable::NON_UNIQUE_NAME, server_name);
427 }
428
429 // The server has the final say on positioning, so apply the absolute
430 // position that it returns.
431 if (entry_response.has_position_in_parent()) {
432 // The SERVER_ field should already have been written.
433 DCHECK_EQ(entry_response.position_in_parent(),
434 local_entry->Get(SERVER_POSITION_IN_PARENT));
435
436 // We just committed successfully, so we assume that the position
437 // value we got applies to the PARENT_ID we submitted.
438 syncable::Id new_prev = local_entry->ComputePrevIdFromServerPosition(
439 local_entry->Get(PARENT_ID));
440 if (!local_entry->PutPredecessor(new_prev))
441 LOG(WARNING) << "PutPredecessor failed after successful commit";
442 }
443 }
444
ProcessSuccessfulCommitResponse(const sync_pb::SyncEntity & committed_entry,const CommitResponse_EntryResponse & entry_response,const syncable::Id & pre_commit_id,syncable::MutableEntry * local_entry,bool syncing_was_set,set<syncable::Id> * deleted_folders)445 void ProcessCommitResponseCommand::ProcessSuccessfulCommitResponse(
446 const sync_pb::SyncEntity& committed_entry,
447 const CommitResponse_EntryResponse& entry_response,
448 const syncable::Id& pre_commit_id, syncable::MutableEntry* local_entry,
449 bool syncing_was_set, set<syncable::Id>* deleted_folders) {
450 DCHECK(local_entry->Get(IS_UNSYNCED));
451
452 // Update SERVER_VERSION and BASE_VERSION.
453 if (!UpdateVersionAfterCommit(committed_entry, entry_response, pre_commit_id,
454 local_entry)) {
455 LOG(ERROR) << "Bad version in commit return for " << *local_entry
456 << " new_id:" << entry_response.id() << " new_version:"
457 << entry_response.version();
458 return;
459 }
460
461 // If the server gave us a new ID, apply it.
462 if (!ChangeIdAfterCommit(entry_response, pre_commit_id, local_entry)) {
463 return;
464 }
465
466 // Update our stored copy of the server state.
467 UpdateServerFieldsAfterCommit(committed_entry, entry_response, local_entry);
468
469 // If the item doesn't need to be committed again (an item might need to be
470 // committed again if it changed locally during the commit), we can remove
471 // it from the unsynced list. Also, we should change the locally-
472 // visible properties to apply any canonicalizations or fixups
473 // that the server introduced during the commit.
474 if (syncing_was_set) {
475 OverrideClientFieldsAfterCommit(committed_entry, entry_response,
476 local_entry);
477 local_entry->Put(IS_UNSYNCED, false);
478 }
479
480 // Make a note of any deleted folders, whose children would have
481 // been recursively deleted.
482 // TODO(nick): Here, commit_message.deleted() would be more correct than
483 // local_entry->Get(IS_DEL). For example, an item could be renamed, and then
484 // deleted during the commit of the rename. Unit test & fix.
485 if (local_entry->Get(IS_DIR) && local_entry->Get(IS_DEL)) {
486 deleted_folders->insert(local_entry->Get(ID));
487 }
488 }
489
490 } // namespace browser_sync
491