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
20using std::string;
21using std::stringstream;
22using syncable::BASE_VERSION;
23using syncable::CTIME;
24using syncable::ID;
25using syncable::IS_DEL;
26using syncable::IS_DIR;
27using syncable::IS_UNSYNCED;
28using syncable::MTIME;
29using syncable::PARENT_ID;
30using syncable::ScopedDirLookup;
31using syncable::SyncName;
32
33namespace browser_sync {
34using sessions::SyncSession;
35
36namespace {
37
38// Time to backoff syncing after receiving a throttled response.
39static const int kSyncDelayAfterThrottled = 2 * 60 * 60;  // 2 hours
40void 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
83void 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
97bool 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
134void 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
141bool 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(&params, &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
184namespace {
185
186// Helper function for an assertion in PostClientToServerMessage.
187bool 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
201bool 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
258bool 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
306void 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
313bool 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
321void 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
328const 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
336const 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
343std::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
360namespace {
361std::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
373std::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