sync/internal_api/http_bridge.cc

   1 // Copyright 2012 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 "sync/internal_api/public/http_bridge.h"
   6
   7 #include "base/message_loop/message_loop.h"
   8 #include "base/metrics/field_trial.h"
   9 #include "base/metrics/histogram_macros.h"
  10 #include "base/strings/string_number_conversions.h"
  11 #include "base/strings/string_util.h"
  12 #include "base/strings/stringprintf.h"
  13 #include "net/base/load_flags.h"
  14 #include "net/base/net_errors.h"
  15 #include "net/http/http_cache.h"
  16 #include "net/http/http_network_layer.h"
  17 #include "net/http/http_request_headers.h"
  18 #include "net/http/http_response_headers.h"
  19 #include "net/url_request/static_http_user_agent_settings.h"
  20 #include "net/url_request/url_fetcher.h"
  21 #include "net/url_request/url_request_context.h"
  22 #include "net/url_request/url_request_job_factory_impl.h"
  23 #include "net/url_request/url_request_status.h"
  24 #include "sync/internal_api/public/base/cancelation_signal.h"
  25 #include "third_party/zlib/zlib.h"
  26
  27 namespace syncer {
  28
  29 namespace {
  30
  31 // It's possible for an http request to be silently stalled. We set a time
  32 // limit for all http requests, beyond which the request is cancelled and
  33 // treated as a transient failure.
  34 const int kMaxHttpRequestTimeSeconds = 60 * 5;  // 5 minutes.
  35
  36 // Helper method for logging timeouts via UMA.
  37 void LogTimeout(bool timed_out) {
  38   UMA_HISTOGRAM_BOOLEAN("Sync.URLFetchTimedOut", timed_out);
  39 }
  40
  41 bool IsSyncHttpContentCompressionEnabled() {
  42   const std::string group_name =
  43       base::FieldTrialList::FindFullName("SyncHttpContentCompression");
  44   return StartsWith(group_name, "Enabled", base::CompareCase::SENSITIVE);
  45 }
  46
  47 void RecordSyncRequestContentLengthHistograms(int64 compressed_content_length,
  48                                               int64 original_content_length) {
  49   UMA_HISTOGRAM_COUNTS("Sync.RequestContentLength.Compressed",
  50                        compressed_content_length);
  51   UMA_HISTOGRAM_COUNTS("Sync.RequestContentLength.Original",
  52                        original_content_length);
  53 }
  54
  55 void RecordSyncResponseContentLengthHistograms(int64 compressed_content_length,
  56                                                int64 original_content_length) {
  57   UMA_HISTOGRAM_COUNTS("Sync.ResponseContentLength.Compressed",
  58                        compressed_content_length);
  59   UMA_HISTOGRAM_COUNTS("Sync.ResponseContentLength.Original",
  60                        original_content_length);
  61 }
  62
  63 // -----------------------------------------------------------------------------
  64 // The rest of the code in the anon namespace is copied from
  65 // components/metrics/compression_utils.cc
  66 // TODO(gangwu): crbug.com/515695. The following code is copied from
  67 // components/metrics/compression_utils.cc. We copied them because if we
  68 // reference them, we will get cycle dependency warning. Once the functions
  69 // have been moved from //component to //base, we can remove the following
  70 // functions.
  71 //------------------------------------------------------------------------------
  72 // The difference in bytes between a zlib header and a gzip header.
  73 const size_t kGzipZlibHeaderDifferenceBytes = 16;
  74
  75 // Pass an integer greater than the following get a gzip header instead of a
  76 // zlib header when calling deflateInit2() and inflateInit2().
  77 const int kWindowBitsToGetGzipHeader = 16;
  78
  79 // This describes the amount of memory zlib uses to compress data. It can go
  80 // from 1 to 9, with 8 being the default. For details, see:
  81 // http://www.zlib.net/manual.html (search for memLevel).
  82 const int kZlibMemoryLevel = 8;
  83
  84 // This code is taken almost verbatim from third_party/zlib/compress.c. The only
  85 // difference is deflateInit2() is called which sets the window bits to be > 16.
  86 // That causes a gzip header to be emitted rather than a zlib header.
  87 int GzipCompressHelper(Bytef* dest,
  88                        uLongf* dest_length,
  89                        const Bytef* source,
  90                        uLong source_length) {
  91   z_stream stream;
  92
  93   stream.next_in = bit_cast<Bytef*>(source);
  94   stream.avail_in = static_cast<uInt>(source_length);
  95   stream.next_out = dest;
  96   stream.avail_out = static_cast<uInt>(*dest_length);
  97   if (static_cast<uLong>(stream.avail_out) != *dest_length)
  98     return Z_BUF_ERROR;
  99
 100   stream.zalloc = static_cast<alloc_func>(0);
 101   stream.zfree = static_cast<free_func>(0);
 102   stream.opaque = static_cast<voidpf>(0);
 103
 104   gz_header gzip_header;
 105   memset(&gzip_header, 0, sizeof(gzip_header));
 106   int err = deflateInit2(&stream, Z_DEFAULT_COMPRESSION, Z_DEFLATED,
 107                          MAX_WBITS + kWindowBitsToGetGzipHeader,
 108                          kZlibMemoryLevel, Z_DEFAULT_STRATEGY);
 109   if (err != Z_OK)
 110     return err;
 111
 112   err = deflateSetHeader(&stream, &gzip_header);
 113   if (err != Z_OK)
 114     return err;
 115
 116   err = deflate(&stream, Z_FINISH);
 117   if (err != Z_STREAM_END) {
 118     deflateEnd(&stream);
 119     return err == Z_OK ? Z_BUF_ERROR : err;
 120   }
 121   *dest_length = stream.total_out;
 122
 123   err = deflateEnd(&stream);
 124   return err;
 125 }
 126
 127 bool GzipCompress(const std::string& input, std::string* output) {
 128   const uLongf input_size = static_cast<uLongf>(input.size());
 129   std::vector<Bytef> compressed_data(kGzipZlibHeaderDifferenceBytes +
 130                                      compressBound(input_size));
 131
 132   uLongf compressed_size = static_cast<uLongf>(compressed_data.size());
 133   if (GzipCompressHelper(&compressed_data.front(), &compressed_size,
 134                          bit_cast<const Bytef*>(input.data()),
 135                          input_size) != Z_OK) {
 136     return false;
 137   }
 138
 139   compressed_data.resize(compressed_size);
 140   output->assign(compressed_data.begin(), compressed_data.end());
 141   return true;
 142 }
 143
 144 }  // namespace
 145
 146 HttpBridgeFactory::HttpBridgeFactory(
 147     const scoped_refptr<net::URLRequestContextGetter>& request_context_getter,
 148     const NetworkTimeUpdateCallback& network_time_update_callback,
 149     CancelationSignal* cancelation_signal)
 150     : request_context_getter_(request_context_getter),
 151       network_time_update_callback_(network_time_update_callback),
 152       cancelation_signal_(cancelation_signal) {
 153   // Registration should never fail.  This should happen on the UI thread during
 154   // init.  It would be impossible for a shutdown to have been requested at this
 155   // point.
 156   bool result = cancelation_signal_->TryRegisterHandler(this);
 157   DCHECK(result);
 158 }
 159
 160 HttpBridgeFactory::~HttpBridgeFactory() {
 161   cancelation_signal_->UnregisterHandler(this);
 162 }
 163
 164 void HttpBridgeFactory::Init(const std::string& user_agent) {
 165   user_agent_ = user_agent;
 166 }
 167
 168 HttpPostProviderInterface* HttpBridgeFactory::Create() {
 169   base::AutoLock lock(request_context_getter_lock_);
 170
 171   // If we've been asked to shut down (something which may happen asynchronously
 172   // and at pretty much any time), then we won't have a request_context_getter_.
 173   // Some external mechanism must ensure that this function is not called after
 174   // we've been asked to shut down.
 175   CHECK(request_context_getter_.get());
 176
 177   scoped_refptr<HttpBridge> http = new HttpBridge(
 178       user_agent_, request_context_getter_, network_time_update_callback_);
 179   http->AddRef();
 180   return http.get();
 181 }
 182
 183 void HttpBridgeFactory::Destroy(HttpPostProviderInterface* http) {
 184   static_cast<HttpBridge*>(http)->Release();
 185 }
 186
 187 void HttpBridgeFactory::OnSignalReceived() {
 188   base::AutoLock lock(request_context_getter_lock_);
 189   // Release |request_context_getter_| as soon as possible so that it
 190   // is destroyed in the right order on its network task runner.
 191   request_context_getter_ = NULL;
 192 }
 193
 194 HttpBridge::URLFetchState::URLFetchState()
 195     : url_poster(NULL),
 196       aborted(false),
 197       request_completed(false),
 198       request_succeeded(false),
 199       http_response_code(-1),
 200       error_code(-1) {
 201 }
 202 HttpBridge::URLFetchState::~URLFetchState() {}
 203
 204 HttpBridge::HttpBridge(
 205     const std::string& user_agent,
 206     const scoped_refptr<net::URLRequestContextGetter>& context_getter,
 207     const NetworkTimeUpdateCallback& network_time_update_callback)
 208     : created_on_loop_(base::MessageLoop::current()),
 209       user_agent_(user_agent),
 210       http_post_completed_(false, false),
 211       request_context_getter_(context_getter),
 212       network_task_runner_(request_context_getter_->GetNetworkTaskRunner()),
 213       network_time_update_callback_(network_time_update_callback) {
 214 }
 215
 216 HttpBridge::~HttpBridge() {
 217 }
 218
 219 void HttpBridge::SetExtraRequestHeaders(const char * headers) {
 220   DCHECK(extra_headers_.empty())
 221       << "HttpBridge::SetExtraRequestHeaders called twice.";
 222   extra_headers_.assign(headers);
 223 }
 224
 225 void HttpBridge::SetURL(const char* url, int port) {
 226 #if DCHECK_IS_ON()
 227   DCHECK_EQ(base::MessageLoop::current(), created_on_loop_);
 228   {
 229     base::AutoLock lock(fetch_state_lock_);
 230     DCHECK(!fetch_state_.request_completed);
 231   }
 232   DCHECK(url_for_request_.is_empty())
 233       << "HttpBridge::SetURL called more than once?!";
 234 #endif
 235   GURL temp(url);
 236   GURL::Replacements replacements;
 237   std::string port_str = base::IntToString(port);
 238   replacements.SetPort(port_str.c_str(), url::Component(0, port_str.length()));
 239   url_for_request_ = temp.ReplaceComponents(replacements);
 240 }
 241
 242 void HttpBridge::SetPostPayload(const char* content_type,
 243                                 int content_length,
 244                                 const char* content) {
 245 #if DCHECK_IS_ON()
 246   DCHECK_EQ(base::MessageLoop::current(), created_on_loop_);
 247   {
 248     base::AutoLock lock(fetch_state_lock_);
 249     DCHECK(!fetch_state_.request_completed);
 250   }
 251   DCHECK(content_type_.empty()) << "Bridge payload already set.";
 252   DCHECK_GE(content_length, 0) << "Content length < 0";
 253 #endif
 254   content_type_ = content_type;
 255   if (!content || (content_length == 0)) {
 256     DCHECK_EQ(content_length, 0);
 257     request_content_ = " ";  // TODO(timsteele): URLFetcher requires non-empty
 258                              // content for POSTs whereas CURL does not, for now
 259                              // we hack this to support the sync backend.
 260   } else {
 261     request_content_.assign(content, content_length);
 262   }
 263 }
 264
 265 bool HttpBridge::MakeSynchronousPost(int* error_code, int* response_code) {
 266 #if DCHECK_IS_ON()
 267   DCHECK_EQ(base::MessageLoop::current(), created_on_loop_);
 268   {
 269     base::AutoLock lock(fetch_state_lock_);
 270     DCHECK(!fetch_state_.request_completed);
 271   }
 272   DCHECK(url_for_request_.is_valid()) << "Invalid URL for request";
 273   DCHECK(!content_type_.empty()) << "Payload not set";
 274 #endif
 275
 276   if (!network_task_runner_->PostTask(
 277           FROM_HERE,
 278           base::Bind(&HttpBridge::CallMakeAsynchronousPost, this))) {
 279     // This usually happens when we're in a unit test.
 280     LOG(WARNING) << "Could not post CallMakeAsynchronousPost task";
 281     return false;
 282   }
 283
 284   // Block until network request completes or is aborted. See
 285   // OnURLFetchComplete and Abort.
 286   http_post_completed_.Wait();
 287
 288   base::AutoLock lock(fetch_state_lock_);
 289   DCHECK(fetch_state_.request_completed || fetch_state_.aborted);
 290   *error_code = fetch_state_.error_code;
 291   *response_code = fetch_state_.http_response_code;
 292   return fetch_state_.request_succeeded;
 293 }
 294
 295 void HttpBridge::MakeAsynchronousPost() {
 296   DCHECK(network_task_runner_->BelongsToCurrentThread());
 297
 298   base::AutoLock lock(fetch_state_lock_);
 299   DCHECK(!fetch_state_.request_completed);
 300   if (fetch_state_.aborted)
 301     return;
 302
 303   // Start the timer on the network thread (the same thread progress is made
 304   // on, and on which the url fetcher lives).
 305   DCHECK(!fetch_state_.http_request_timeout_timer.get());
 306   fetch_state_.http_request_timeout_timer.reset(new base::Timer(false, false));
 307   fetch_state_.http_request_timeout_timer->Start(
 308       FROM_HERE, base::TimeDelta::FromSeconds(kMaxHttpRequestTimeSeconds),
 309       base::Bind(&HttpBridge::OnURLFetchTimedOut, this));
 310
 311   DCHECK(request_context_getter_.get());
 312   fetch_state_.start_time = base::Time::Now();
 313   fetch_state_.url_poster =
 314       net::URLFetcher::Create(url_for_request_, net::URLFetcher::POST, this)
 315           .release();
 316   fetch_state_.url_poster->SetRequestContext(request_context_getter_.get());
 317   fetch_state_.url_poster->SetExtraRequestHeaders(extra_headers_);
 318
 319   int64 compressed_content_size = 0;
 320   if (IsSyncHttpContentCompressionEnabled()) {
 321     std::string compressed_request_content;
 322     GzipCompress(request_content_, &compressed_request_content);
 323     compressed_content_size = compressed_request_content.size();
 324     fetch_state_.url_poster->SetUploadData(content_type_,
 325                                            compressed_request_content);
 326     fetch_state_.url_poster->AddExtraRequestHeader("Content-Encoding: gzip");
 327   } else {
 328     fetch_state_.url_poster->SetUploadData(content_type_, request_content_);
 329     fetch_state_.url_poster->AddExtraRequestHeader(base::StringPrintf(
 330         "%s: %s", net::HttpRequestHeaders::kAcceptEncoding, "deflate"));
 331   }
 332
 333   RecordSyncRequestContentLengthHistograms(compressed_content_size,
 334                                            request_content_.size());
 335
 336   fetch_state_.url_poster->AddExtraRequestHeader(base::StringPrintf(
 337       "%s: %s", net::HttpRequestHeaders::kUserAgent, user_agent_.c_str()));
 338   fetch_state_.url_poster->SetLoadFlags(net::LOAD_BYPASS_CACHE |
 339                                         net::LOAD_DISABLE_CACHE |
 340                                         net::LOAD_DO_NOT_SAVE_COOKIES |
 341                                         net::LOAD_DO_NOT_SEND_COOKIES);
 342
 343   fetch_state_.url_poster->Start();
 344 }
 345
 346 int HttpBridge::GetResponseContentLength() const {
 347   DCHECK_EQ(base::MessageLoop::current(), created_on_loop_);
 348   base::AutoLock lock(fetch_state_lock_);
 349   DCHECK(fetch_state_.request_completed);
 350   return fetch_state_.response_content.size();
 351 }
 352
 353 const char* HttpBridge::GetResponseContent() const {
 354   DCHECK_EQ(base::MessageLoop::current(), created_on_loop_);
 355   base::AutoLock lock(fetch_state_lock_);
 356   DCHECK(fetch_state_.request_completed);
 357   return fetch_state_.response_content.data();
 358 }
 359
 360 const std::string HttpBridge::GetResponseHeaderValue(
 361     const std::string& name) const {
 362
 363   DCHECK_EQ(base::MessageLoop::current(), created_on_loop_);
 364   base::AutoLock lock(fetch_state_lock_);
 365   DCHECK(fetch_state_.request_completed);
 366
 367   std::string value;
 368   fetch_state_.response_headers->EnumerateHeader(NULL, name, &value);
 369   return value;
 370 }
 371
 372 void HttpBridge::Abort() {
 373   base::AutoLock lock(fetch_state_lock_);
 374
 375   // Release |request_context_getter_| as soon as possible so that it is
 376   // destroyed in the right order on its network task runner.
 377   request_context_getter_ = NULL;
 378
 379   DCHECK(!fetch_state_.aborted);
 380   if (fetch_state_.aborted || fetch_state_.request_completed)
 381     return;
 382
 383   fetch_state_.aborted = true;
 384   if (!network_task_runner_->PostTask(
 385           FROM_HERE,
 386           base::Bind(&HttpBridge::DestroyURLFetcherOnIOThread, this,
 387                      fetch_state_.url_poster,
 388                      fetch_state_.http_request_timeout_timer.release()))) {
 389     // Madness ensues.
 390     NOTREACHED() << "Could not post task to delete URLFetcher";
 391   }
 392
 393   fetch_state_.url_poster = NULL;
 394   fetch_state_.error_code = net::ERR_ABORTED;
 395   http_post_completed_.Signal();
 396 }
 397
 398 void HttpBridge::DestroyURLFetcherOnIOThread(
 399     net::URLFetcher* fetcher,
 400     base::Timer* fetch_timer) {
 401   DCHECK(network_task_runner_->BelongsToCurrentThread());
 402   if (fetch_timer)
 403     delete fetch_timer;
 404   delete fetcher;
 405 }
 406
 407 void HttpBridge::OnURLFetchComplete(const net::URLFetcher* source) {
 408   DCHECK(network_task_runner_->BelongsToCurrentThread());
 409
 410   base::AutoLock lock(fetch_state_lock_);
 411
 412   // Stop the request timer now that the request completed.
 413   if (fetch_state_.http_request_timeout_timer.get())
 414     fetch_state_.http_request_timeout_timer.reset();
 415
 416   if (fetch_state_.aborted)
 417     return;
 418
 419   fetch_state_.end_time = base::Time::Now();
 420   fetch_state_.request_completed = true;
 421   fetch_state_.request_succeeded =
 422       (net::URLRequestStatus::SUCCESS == source->GetStatus().status());
 423   fetch_state_.http_response_code = source->GetResponseCode();
 424   fetch_state_.error_code = source->GetStatus().error();
 425
 426   if (fetch_state_.request_succeeded)
 427     LogTimeout(false);
 428   UMA_HISTOGRAM_LONG_TIMES("Sync.URLFetchTime",
 429                            fetch_state_.end_time - fetch_state_.start_time);
 430
 431   // Use a real (non-debug) log to facilitate troubleshooting in the wild.
 432   VLOG(2) << "HttpBridge::OnURLFetchComplete for: "
 433           << fetch_state_.url_poster->GetURL().spec();
 434   VLOG(1) << "HttpBridge received response code: "
 435           << fetch_state_.http_response_code;
 436
 437   source->GetResponseAsString(&fetch_state_.response_content);
 438   fetch_state_.response_headers = source->GetResponseHeaders();
 439   UpdateNetworkTime();
 440
 441   int64 compressed_content_length = fetch_state_.response_content.size();
 442   int64 original_content_length = compressed_content_length;
 443   if (fetch_state_.response_headers &&
 444       fetch_state_.response_headers->HasHeaderValue("content-encoding",
 445                                                     "gzip")) {
 446     compressed_content_length =
 447         fetch_state_.response_headers->GetContentLength();
 448   }
 449   RecordSyncResponseContentLengthHistograms(compressed_content_length,
 450                                             original_content_length);
 451
 452   // End of the line for url_poster_. It lives only on the IO loop.
 453   // We defer deletion because we're inside a callback from a component of the
 454   // URLFetcher, so it seems most natural / "polite" to let the stack unwind.
 455   base::MessageLoop::current()->DeleteSoon(FROM_HERE, fetch_state_.url_poster);
 456   fetch_state_.url_poster = NULL;
 457
 458   // Wake the blocked syncer thread in MakeSynchronousPost.
 459   // WARNING: DONT DO ANYTHING AFTER THIS CALL! |this| may be deleted!
 460   http_post_completed_.Signal();
 461 }
 462
 463 void HttpBridge::OnURLFetchDownloadProgress(const net::URLFetcher* source,
 464                                             int64 current, int64 total) {
 465   DCHECK(network_task_runner_->BelongsToCurrentThread());
 466   // Reset the delay when forward progress is made.
 467   base::AutoLock lock(fetch_state_lock_);
 468   if (fetch_state_.http_request_timeout_timer.get())
 469     fetch_state_.http_request_timeout_timer->Reset();
 470 }
 471
 472 void HttpBridge::OnURLFetchUploadProgress(const net::URLFetcher* source,
 473                                           int64 current, int64 total) {
 474   DCHECK(network_task_runner_->BelongsToCurrentThread());
 475   // Reset the delay when forward progress is made.
 476   base::AutoLock lock(fetch_state_lock_);
 477   if (fetch_state_.http_request_timeout_timer.get())
 478     fetch_state_.http_request_timeout_timer->Reset();
 479 }
 480
 481 void HttpBridge::OnURLFetchTimedOut() {
 482   DCHECK(network_task_runner_->BelongsToCurrentThread());
 483
 484   base::AutoLock lock(fetch_state_lock_);
 485   if (!fetch_state_.url_poster)
 486     return;
 487
 488   LogTimeout(true);
 489   DVLOG(1) << "Sync url fetch timed out. Canceling.";
 490
 491   fetch_state_.end_time = base::Time::Now();
 492   fetch_state_.request_completed = true;
 493   fetch_state_.request_succeeded = false;
 494   fetch_state_.http_response_code = -1;
 495   fetch_state_.error_code = net::URLRequestStatus::FAILED;
 496
 497   // This method is called by the timer, not the url fetcher implementation,
 498   // so it's safe to delete the fetcher here.
 499   delete fetch_state_.url_poster;
 500   fetch_state_.url_poster = NULL;
 501
 502   // Timer is smart enough to handle being deleted as part of the invoked task.
 503   fetch_state_.http_request_timeout_timer.reset();
 504
 505   // Wake the blocked syncer thread in MakeSynchronousPost.
 506   // WARNING: DONT DO ANYTHING AFTER THIS CALL! |this| may be deleted!
 507   http_post_completed_.Signal();
 508 }
 509
 510 net::URLRequestContextGetter* HttpBridge::GetRequestContextGetterForTest()
 511     const {
 512   base::AutoLock lock(fetch_state_lock_);
 513   return request_context_getter_.get();
 514 }
 515
 516 void HttpBridge::UpdateNetworkTime() {
 517   std::string sane_time_str;
 518   if (!fetch_state_.request_succeeded || fetch_state_.start_time.is_null() ||
 519       fetch_state_.end_time < fetch_state_.start_time ||
 520       !fetch_state_.response_headers ||
 521       !fetch_state_.response_headers->EnumerateHeader(NULL, "Sane-Time-Millis",
 522                                                       &sane_time_str)) {
 523     return;
 524   }
 525
 526   int64 sane_time_ms = 0;
 527   if (base::StringToInt64(sane_time_str, &sane_time_ms)) {
 528     network_time_update_callback_.Run(
 529         base::Time::FromJsTime(sane_time_ms),
 530         base::TimeDelta::FromMilliseconds(1),
 531         fetch_state_.end_time - fetch_state_.start_time);
 532   }
 533 }
 534
 535 }  // namespace syncer