Home | History | Annotate | Download | only in engine 
      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 
     50 void IncrementErrorCounters(StatusController* status) {
     51   status->increment_num_consecutive_errors();
     52 }
     53 void ResetErrorCounters(StatusController* status) {
     54   status->set_num_consecutive_errors(0);
     55 }
     56 
     57 ProcessCommitResponseCommand::ProcessCommitResponseCommand() {}
     58 ProcessCommitResponseCommand::~ProcessCommitResponseCommand() {}
     59 
     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 
     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 
    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 
    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
    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 
    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 
    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 
    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 
    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 
    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 
    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