path: root/chrome/browser/sync/engine/process_commit_response_command.cc

// Copyright (c) 2006-2009 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/process_commit_response_command.h"

#include <set>
#include <string>
#include <vector>

#include "base/basictypes.h"
#include "chrome/browser/sync/engine/syncer_proto_util.h"
#include "chrome/browser/sync/engine/syncer_util.h"
#include "chrome/browser/sync/engine/syncproto.h"
#include "chrome/browser/sync/sessions/sync_session.h"
#include "chrome/browser/sync/syncable/directory_manager.h"
#include "chrome/browser/sync/syncable/syncable.h"

using syncable::ScopedDirLookup;
using syncable::WriteTransaction;
using syncable::MutableEntry;
using syncable::Entry;

using std::set;
using std::string;
using std::vector;

using syncable::BASE_VERSION;
using syncable::GET_BY_ID;
using syncable::ID;
using syncable::IS_DEL;
using syncable::IS_DIR;
using syncable::IS_UNAPPLIED_UPDATE;
using syncable::IS_UNSYNCED;
using syncable::PARENT_ID;
using syncable::SERVER_PARENT_ID;
using syncable::SERVER_POSITION_IN_PARENT;
using syncable::SYNCER;
using syncable::SYNCING;

namespace browser_sync {

using sessions::StatusController;
using sessions::SyncSession;
using sessions::ConflictProgress;

void IncrementErrorCounters(StatusController* status) {
  status->increment_num_consecutive_problem_commits();
  status->increment_num_consecutive_errors();
}
void ResetErrorCounters(StatusController* status) {
  status->set_num_consecutive_problem_commits(0);
  status->set_num_consecutive_errors(0);
}

ProcessCommitResponseCommand::ProcessCommitResponseCommand() {}
ProcessCommitResponseCommand::~ProcessCommitResponseCommand() {}

void ProcessCommitResponseCommand::ModelChangingExecuteImpl(
    SyncSession* session) {
  ProcessCommitResponse(session);
  ExtensionsActivityMonitor* monitor = session->context()->extensions_monitor();
  if (session->status_controller()->syncer_status().num_successful_commits == 0)
    monitor->PutRecords(session->extensions_activity());
}

void ProcessCommitResponseCommand::ProcessCommitResponse(
    SyncSession* session) {
  // TODO(sync): This function returns if it sees problems. We probably want
  // to flag the need for an update or similar.
  ScopedDirLookup dir(session->context()->directory_manager(),
                      session->context()->account_name());
  if (!dir.good()) {
    LOG(ERROR) << "Scoped dir lookup failed!";
    return;
  }

  StatusController* status = session->status_controller();
  const ClientToServerResponse& response(status->commit_response());
  const vector<syncable::Id>& commit_ids(status->commit_ids());

  if (!response.has_commit()) {
    // TODO(sync): What if we didn't try to commit anything?
    LOG(WARNING) << "Commit response has no commit body!";
    IncrementErrorCounters(status);
    return;
  }

  const CommitResponse& cr = response.commit();
  int commit_count = commit_ids.size();
  if (cr.entryresponse_size() != commit_count) {
    LOG(ERROR) << "Commit response has wrong number of entries! Expected:" <<
               commit_count << " Got:" << cr.entryresponse_size();
    for (int i = 0 ; i < cr.entryresponse_size() ; i++) {
      LOG(ERROR) << "Response #" << i << " Value: " <<
                 cr.entryresponse(i).response_type();
      if (cr.entryresponse(i).has_error_message())
        LOG(ERROR) << "  " << cr.entryresponse(i).error_message();
    }
    IncrementErrorCounters(status);
    return;
  }

  // If we try to commit a parent and child together and the parent conflicts
  // the child will have a bad parent causing an error. As this is not a
  // critical error, we trap it and don't LOG(ERROR). To enable this we keep
  // a map of conflicting new folders.
  int transient_error_commits = 0;
  int conflicting_commits = 0;
  int error_commits = 0;
  int successes = 0;
  bool over_quota = false;
  set<syncable::Id> conflicting_new_folder_ids;
  set<syncable::Id> deleted_folders;
  ConflictProgress* conflict_progress = status->mutable_conflict_progress();
  { // Scope for WriteTransaction.
    WriteTransaction trans(dir, SYNCER, __FILE__, __LINE__);
    for (int i = 0; i < cr.entryresponse_size(); i++) {
      CommitResponse::ResponseType response_type =
          ProcessSingleCommitResponse(&trans, cr.entryresponse(i),
                                      commit_ids[i],
                                      &conflicting_new_folder_ids,
                                      &deleted_folders);
      switch (response_type) {
        case CommitResponse::INVALID_MESSAGE:
          ++error_commits;
          break;
        case CommitResponse::CONFLICT:
          ++conflicting_commits;
          // Only server CONFLICT responses will activate conflict resolution.
          conflict_progress->AddConflictingItemById(commit_ids[i]);
          break;
        case CommitResponse::SUCCESS:
          // TODO(sync): worry about sync_rate_ rate calc?
          ++successes;
          status->increment_num_successful_commits();
          break;
        case CommitResponse::OVER_QUOTA:
          over_quota = true;
          // We handle over quota like a retry, which is same as transient.
        case CommitResponse::RETRY:
        case CommitResponse::TRANSIENT_ERROR:
          // TODO(tim): Now that we have SyncSession::Delegate, we
          // should plumb this directly for exponential backoff purposes rather
          // than trying to infer from HasMoreToSync(). See
          // SyncerThread::CalculatePollingWaitTime.
          ++transient_error_commits;
          break;
        default:
          LOG(FATAL) << "Bad return from ProcessSingleCommitResponse";
      }
    }
  }

  // TODO(sync): move status reporting elsewhere.
  status->set_num_conflicting_commits(conflicting_commits);
  if (0 == successes) {
    status->increment_num_consecutive_transient_error_commits_by(
        transient_error_commits);
    status->increment_num_consecutive_errors_by(transient_error_commits);
  } else {
    status->set_num_consecutive_transient_error_commits(0);
    status->set_num_consecutive_errors(0);
  }
  if (commit_count != (conflicting_commits + error_commits +
                       transient_error_commits)) {
    ResetErrorCounters(status);
  }
  SyncerUtil::MarkDeletedChildrenSynced(dir, &deleted_folders);
  status->set_over_quota(over_quota);

  return;
}

void LogServerError(const CommitResponse_EntryResponse& res) {
  if (res.has_error_message())
    LOG(ERROR) << "  " << res.error_message();
  else
    LOG(ERROR) << "  No detailed error message returned from server";
}

CommitResponse::ResponseType
ProcessCommitResponseCommand::ProcessSingleCommitResponse(
    syncable::WriteTransaction* trans,
    const sync_pb::CommitResponse_EntryResponse& pb_server_entry,
    const syncable::Id& pre_commit_id,
    std::set<syncable::Id>* conflicting_new_folder_ids,
    set<syncable::Id>* deleted_folders) {

  const CommitResponse_EntryResponse& server_entry =
      *static_cast<const CommitResponse_EntryResponse*>(&pb_server_entry);
  MutableEntry local_entry(trans, GET_BY_ID, pre_commit_id);
  CHECK(local_entry.good());
  bool syncing_was_set = local_entry.Get(SYNCING);
  local_entry.Put(SYNCING, false);

  CommitResponse::ResponseType response = (CommitResponse::ResponseType)
      server_entry.response_type();
  if (!CommitResponse::ResponseType_IsValid(response)) {
    LOG(ERROR) << "Commit response has unknown response type! Possibly out "
               "of date client?";
    return CommitResponse::INVALID_MESSAGE;
  }
  if (CommitResponse::TRANSIENT_ERROR == response) {
    LOG(INFO) << "Transient Error Committing: " << local_entry;
    LogServerError(server_entry);
    return CommitResponse::TRANSIENT_ERROR;
  }
  if (CommitResponse::INVALID_MESSAGE == response) {
    LOG(ERROR) << "Error Commiting: " << local_entry;
    LogServerError(server_entry);
    return response;
  }
  if (CommitResponse::CONFLICT == response) {
    LOG(INFO) << "Conflict Committing: " << local_entry;
    if (!pre_commit_id.ServerKnows() && local_entry.Get(IS_DIR)) {
      conflicting_new_folder_ids->insert(pre_commit_id);
    }
    return response;
  }
  if (CommitResponse::RETRY == response) {
    LOG(INFO) << "Retry Committing: " << local_entry;
    return response;
  }
  if (CommitResponse::OVER_QUOTA == response) {
    LOG(INFO) << "Hit Quota Committing: " << local_entry;
    return response;
  }
  if (!server_entry.has_id_string()) {
    LOG(ERROR) << "Commit response has no id";
    return CommitResponse::INVALID_MESSAGE;
  }

  // Implied by the IsValid call above, but here for clarity.
  DCHECK_EQ(CommitResponse::SUCCESS, response) << response;
  // Check to see if we've been given the ID of an existing entry. If so treat
  // it as an error response and retry later.
  if (pre_commit_id != server_entry.id()) {
    Entry e(trans, GET_BY_ID, server_entry.id());
    if (e.good()) {
      LOG(ERROR) << "Got duplicate id when commiting id: " << pre_commit_id <<
                 ". Treating as an error return";
      return CommitResponse::INVALID_MESSAGE;
    }
  }

  if (server_entry.version() == 0) {
    LOG(WARNING) << "Server returned a zero version on a commit response.";
  }

  ProcessSuccessfulCommitResponse(trans, server_entry, pre_commit_id,
                                  &local_entry, syncing_was_set,
                                  deleted_folders);
  return response;
}

void ProcessCommitResponseCommand::ProcessSuccessfulCommitResponse(
    syncable::WriteTransaction* trans,
    const CommitResponse_EntryResponse& server_entry,
    const syncable::Id& pre_commit_id, syncable::MutableEntry* local_entry,
    bool syncing_was_set, set<syncable::Id>* deleted_folders) {
  int64 old_version = local_entry->Get(BASE_VERSION);
  int64 new_version = server_entry.version();
  bool bad_commit_version = false;
  // TODO(sync): The !server_entry.has_id_string() clauses below were
  // introduced when working with the new protocol.
  if (!pre_commit_id.ServerKnows())
    bad_commit_version = 0 == new_version;
  else
    bad_commit_version = old_version > new_version;
  if (bad_commit_version) {
    LOG(ERROR) << "Bad version in commit return for " << *local_entry <<
        " new_id:" << server_entry.id() << " new_version:" <<
        server_entry.version();
    return;
  }
  if (server_entry.id() != pre_commit_id) {
    if (pre_commit_id.ServerKnows()) {
      // TODO(sync): In future it's possible that we'll want the opportunity
      // to do a server triggered move aside here.
      LOG(ERROR) << " ID change but not committing a new entry. " <<
          pre_commit_id << " became " << server_entry.id() << ".";
      return;
    }
    if (!server_entry.id().ServerKnows()) {
      LOG(ERROR) << " New entries id < 0." << pre_commit_id << " became " <<
          server_entry.id() << ".";
      return;
    }
    MutableEntry same_id(trans, GET_BY_ID, server_entry.id());
    // We should trap this before this function.
    CHECK(!same_id.good()) << "ID clash with id " << server_entry.id() <<
        " during commit " << same_id;
    SyncerUtil::ChangeEntryIDAndUpdateChildren(
        trans, local_entry, server_entry.id());
    LOG(INFO) << "Changing ID to " << server_entry.id();
  }

  local_entry->Put(BASE_VERSION, new_version);
  LOG(INFO) << "Commit is changing base version of " <<
    local_entry->Get(ID) << " to: " << new_version;

  if (local_entry->Get(IS_UNAPPLIED_UPDATE)) {
    // This is possible, but very unlikely.
    local_entry->Put(IS_UNAPPLIED_UPDATE, false);
  }

  if (server_entry.has_name()) {
    if (syncing_was_set) {
      PerformCommitTimeNameAside(trans, server_entry, local_entry);
    } else {
      // IS_UNSYNCED will ensure that this entry gets committed again, even if
      // we skip this name aside. IS_UNSYNCED was probably previously set, but
      // let's just set it anyway.
      local_entry->Put(IS_UNSYNCED, true);
      LOG(INFO) << "Skipping commit time name aside because" <<
          " entry was changed during commit.";
    }
  }

  if (syncing_was_set && server_entry.has_position_in_parent()) {
    // The server has the final say on positioning, so apply the absolute
    // position that it returns.
    local_entry->Put(SERVER_POSITION_IN_PARENT,
        server_entry.position_in_parent());

    // We just committed successfully, so we assume that the position
    // value we got applies to the PARENT_ID we submitted.
    syncable::Id new_prev = SyncerUtil::ComputePrevIdFromServerPosition(
        trans, local_entry, local_entry->Get(PARENT_ID));
    if (!local_entry->PutPredecessor(new_prev)) {
      LOG(WARNING) << "PutPredecessor failed after successful commit";
    }
  }

  if (syncing_was_set) {
    local_entry->Put(IS_UNSYNCED, false);
  }
  if (local_entry->Get(IS_DIR) && local_entry->Get(IS_DEL)) {
    deleted_folders->insert(local_entry->Get(ID));
  }
}

void ProcessCommitResponseCommand::PerformCommitTimeNameAside(
    syncable::WriteTransaction* trans,
    const CommitResponse_EntryResponse& server_entry,
    syncable::MutableEntry* local_entry) {
  string old_name = local_entry->Get(syncable::NON_UNIQUE_NAME);
  const string server_name =
      SyncerProtoUtil::NameFromCommitEntryResponse(server_entry);

  if (!server_name.empty() && old_name != server_name) {
    LOG(INFO) << "Server commit moved aside entry: " << old_name
              << " to new name " << server_name;
    // Should be safe since we're in a "commit lock."
    local_entry->Put(syncable::NON_UNIQUE_NAME, server_name);
  }
}

}  // namespace browser_sync