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/compression/compression_utils.cc
  66 // TODO(gangwu): crbug.com/515695. The following code is copied from
  67 // components/compression/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(
 165     const std::string& user_agent,
 166     const BindToTrackerCallback& bind_to_tracker_callback) {
 167   user_agent_ = user_agent;
 168   bind_to_tracker_callback_ = bind_to_tracker_callback;
 169 }
 170
 171 HttpPostProviderInterface* HttpBridgeFactory::Create() {
 172   base::AutoLock lock(request_context_getter_lock_);
 173
 174   // If we've been asked to shut down (something which may happen asynchronously
 175   // and at pretty much any time), then we won't have a request_context_getter_.
 176   // Some external mechanism must ensure that this function is not called after
 177   // we've been asked to shut down.
 178   CHECK(request_context_getter_.get());
 179
 180   scoped_refptr<HttpBridge> http =
 181       new HttpBridge(user_agent_, request_context_getter_,
 182                      network_time_update_callback_, bind_to_tracker_callback_);
 183   http->AddRef();
 184   return http.get();
 185 }
 186
 187 void HttpBridgeFactory::Destroy(HttpPostProviderInterface* http) {
 188   static_cast<HttpBridge*>(http)->Release();
 189 }
 190
 191 void HttpBridgeFactory::OnSignalReceived() {
 192   base::AutoLock lock(request_context_getter_lock_);
 193   // Release |request_context_getter_| as soon as possible so that it
 194   // is destroyed in the right order on its network task runner.
 195   request_context_getter_ = NULL;
 196 }
 197
 198 HttpBridge::URLFetchState::URLFetchState()
 199     : url_poster(NULL),
 200       aborted(false),
 201       request_completed(false),
 202       request_succeeded(false),
 203       http_response_code(-1),
 204       error_code(-1) {
 205 }
 206 HttpBridge::URLFetchState::~URLFetchState() {}
 207
 208 HttpBridge::HttpBridge(
 209     const std::string& user_agent,
 210     const scoped_refptr<net::URLRequestContextGetter>& context_getter,
 211     const NetworkTimeUpdateCallback& network_time_update_callback,
 212     const BindToTrackerCallback& bind_to_tracker_callback)
 213     : created_on_loop_(base::MessageLoop::current()),
 214       user_agent_(user_agent),
 215       http_post_completed_(false, false),
 216       request_context_getter_(context_getter),
 217       network_task_runner_(request_context_getter_->GetNetworkTaskRunner()),
 218       network_time_update_callback_(network_time_update_callback),
 219       bind_to_tracker_callback_(bind_to_tracker_callback) {}
 220
 221 HttpBridge::~HttpBridge() {
 222 }
 223
 224 void HttpBridge::SetExtraRequestHeaders(const char * headers) {
 225   DCHECK(extra_headers_.empty())
 226       << "HttpBridge::SetExtraRequestHeaders called twice.";
 227   extra_headers_.assign(headers);
 228 }
 229
 230 void HttpBridge::SetURL(const char* url, int port) {
 231 #if DCHECK_IS_ON()
 232   DCHECK_EQ(base::MessageLoop::current(), created_on_loop_);
 233   {
 234     base::AutoLock lock(fetch_state_lock_);
 235     DCHECK(!fetch_state_.request_completed);
 236   }
 237   DCHECK(url_for_request_.is_empty())
 238       << "HttpBridge::SetURL called more than once?!";
 239 #endif
 240   GURL temp(url);
 241   GURL::Replacements replacements;
 242   std::string port_str = base::IntToString(port);
 243   replacements.SetPort(port_str.c_str(), url::Component(0, port_str.length()));
 244   url_for_request_ = temp.ReplaceComponents(replacements);
 245 }
 246
 247 void HttpBridge::SetPostPayload(const char* content_type,
 248                                 int content_length,
 249                                 const char* content) {
 250 #if DCHECK_IS_ON()
 251   DCHECK_EQ(base::MessageLoop::current(), created_on_loop_);
 252   {
 253     base::AutoLock lock(fetch_state_lock_);
 254     DCHECK(!fetch_state_.request_completed);
 255   }
 256   DCHECK(content_type_.empty()) << "Bridge payload already set.";
 257   DCHECK_GE(content_length, 0) << "Content length < 0";
 258 #endif
 259   content_type_ = content_type;
 260   if (!content || (content_length == 0)) {
 261     DCHECK_EQ(content_length, 0);
 262     request_content_ = " ";  // TODO(timsteele): URLFetcher requires non-empty
 263                              // content for POSTs whereas CURL does not, for now
 264                              // we hack this to support the sync backend.
 265   } else {
 266     request_content_.assign(content, content_length);
 267   }
 268 }
 269
 270 bool HttpBridge::MakeSynchronousPost(int* error_code, int* response_code) {
 271 #if DCHECK_IS_ON()
 272   DCHECK_EQ(base::MessageLoop::current(), created_on_loop_);
 273   {
 274     base::AutoLock lock(fetch_state_lock_);
 275     DCHECK(!fetch_state_.request_completed);
 276   }
 277   DCHECK(url_for_request_.is_valid()) << "Invalid URL for request";
 278   DCHECK(!content_type_.empty()) << "Payload not set";
 279 #endif
 280
 281   if (!network_task_runner_->PostTask(
 282           FROM_HERE,
 283           base::Bind(&HttpBridge::CallMakeAsynchronousPost, this))) {
 284     // This usually happens when we're in a unit test.
 285     LOG(WARNING) << "Could not post CallMakeAsynchronousPost task";
 286     return false;
 287   }
 288
 289   // Block until network request completes or is aborted. See
 290   // OnURLFetchComplete and Abort.
 291   http_post_completed_.Wait();
 292
 293   base::AutoLock lock(fetch_state_lock_);
 294   DCHECK(fetch_state_.request_completed || fetch_state_.aborted);
 295   *error_code = fetch_state_.error_code;
 296   *response_code = fetch_state_.http_response_code;
 297   return fetch_state_.request_succeeded;
 298 }
 299
 300 void HttpBridge::MakeAsynchronousPost() {
 301   DCHECK(network_task_runner_->BelongsToCurrentThread());
 302
 303   base::AutoLock lock(fetch_state_lock_);
 304   DCHECK(!fetch_state_.request_completed);
 305   if (fetch_state_.aborted)
 306     return;
 307
 308   // Start the timer on the network thread (the same thread progress is made
 309   // on, and on which the url fetcher lives).
 310   DCHECK(!fetch_state_.http_request_timeout_timer.get());
 311   fetch_state_.http_request_timeout_timer.reset(new base::Timer(false, false));
 312   fetch_state_.http_request_timeout_timer->Start(
 313       FROM_HERE, base::TimeDelta::FromSeconds(kMaxHttpRequestTimeSeconds),
 314       base::Bind(&HttpBridge::OnURLFetchTimedOut, this));
 315
 316   DCHECK(request_context_getter_.get());
 317   fetch_state_.start_time = base::Time::Now();
 318   fetch_state_.url_poster =
 319       net::URLFetcher::Create(url_for_request_, net::URLFetcher::POST, this)
 320           .release();
 321   if (!bind_to_tracker_callback_.is_null())
 322     bind_to_tracker_callback_.Run(fetch_state_.url_poster);
 323   fetch_state_.url_poster->SetRequestContext(request_context_getter_.get());
 324   fetch_state_.url_poster->SetExtraRequestHeaders(extra_headers_);
 325
 326   int64 compressed_content_size = 0;
 327   if (IsSyncHttpContentCompressionEnabled()) {
 328     std::string compressed_request_content;
 329     GzipCompress(request_content_, &compressed_request_content);
 330     compressed_content_size = compressed_request_content.size();
 331     fetch_state_.url_poster->SetUploadData(content_type_,
 332                                            compressed_request_content);
 333     fetch_state_.url_poster->AddExtraRequestHeader("Content-Encoding: gzip");
 334   } else {
 335     fetch_state_.url_poster->SetUploadData(content_type_, request_content_);
 336     fetch_state_.url_poster->AddExtraRequestHeader(base::StringPrintf(
 337         "%s: %s", net::HttpRequestHeaders::kAcceptEncoding, "deflate"));
 338   }
 339
 340   RecordSyncRequestContentLengthHistograms(compressed_content_size,
 341                                            request_content_.size());
 342
 343   fetch_state_.url_poster->AddExtraRequestHeader(base::StringPrintf(
 344       "%s: %s", net::HttpRequestHeaders::kUserAgent, user_agent_.c_str()));
 345   fetch_state_.url_poster->SetLoadFlags(net::LOAD_BYPASS_CACHE |
 346                                         net::LOAD_DISABLE_CACHE |
 347                                         net::LOAD_DO_NOT_SAVE_COOKIES |
 348                                         net::LOAD_DO_NOT_SEND_COOKIES);
 349
 350   fetch_state_.url_poster->Start();
 351 }
 352
 353 int HttpBridge::GetResponseContentLength() 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.size();
 358 }
 359
 360 const char* HttpBridge::GetResponseContent() const {
 361   DCHECK_EQ(base::MessageLoop::current(), created_on_loop_);
 362   base::AutoLock lock(fetch_state_lock_);
 363   DCHECK(fetch_state_.request_completed);
 364   return fetch_state_.response_content.data();
 365 }
 366
 367 const std::string HttpBridge::GetResponseHeaderValue(
 368     const std::string& name) const {
 369
 370   DCHECK_EQ(base::MessageLoop::current(), created_on_loop_);
 371   base::AutoLock lock(fetch_state_lock_);
 372   DCHECK(fetch_state_.request_completed);
 373
 374   std::string value;
 375   fetch_state_.response_headers->EnumerateHeader(NULL, name, &value);
 376   return value;
 377 }
 378
 379 void HttpBridge::Abort() {
 380   base::AutoLock lock(fetch_state_lock_);
 381
 382   // Release |request_context_getter_| as soon as possible so that it is
 383   // destroyed in the right order on its network task runner.
 384   request_context_getter_ = NULL;
 385
 386   DCHECK(!fetch_state_.aborted);
 387   if (fetch_state_.aborted || fetch_state_.request_completed)
 388     return;
 389
 390   fetch_state_.aborted = true;
 391   if (!network_task_runner_->PostTask(
 392           FROM_HERE,
 393           base::Bind(&HttpBridge::DestroyURLFetcherOnIOThread, this,
 394                      fetch_state_.url_poster,
 395                      fetch_state_.http_request_timeout_timer.release()))) {
 396     // Madness ensues.
 397     NOTREACHED() << "Could not post task to delete URLFetcher";
 398   }
 399
 400   fetch_state_.url_poster = NULL;
 401   fetch_state_.error_code = net::ERR_ABORTED;
 402   http_post_completed_.Signal();
 403 }
 404
 405 void HttpBridge::DestroyURLFetcherOnIOThread(
 406     net::URLFetcher* fetcher,
 407     base::Timer* fetch_timer) {
 408   DCHECK(network_task_runner_->BelongsToCurrentThread());
 409   if (fetch_timer)
 410     delete fetch_timer;
 411   delete fetcher;
 412 }
 413
 414 void HttpBridge::OnURLFetchComplete(const net::URLFetcher* source) {
 415   DCHECK(network_task_runner_->BelongsToCurrentThread());
 416
 417   base::AutoLock lock(fetch_state_lock_);
 418
 419   // Stop the request timer now that the request completed.
 420   if (fetch_state_.http_request_timeout_timer.get())
 421     fetch_state_.http_request_timeout_timer.reset();
 422
 423   if (fetch_state_.aborted)
 424     return;
 425
 426   fetch_state_.end_time = base::Time::Now();
 427   fetch_state_.request_completed = true;
 428   fetch_state_.request_succeeded =
 429       (net::URLRequestStatus::SUCCESS == source->GetStatus().status());
 430   fetch_state_.http_response_code = source->GetResponseCode();
 431   fetch_state_.error_code = source->GetStatus().error();
 432
 433   if (fetch_state_.request_succeeded)
 434     LogTimeout(false);
 435   UMA_HISTOGRAM_LONG_TIMES("Sync.URLFetchTime",
 436                            fetch_state_.end_time - fetch_state_.start_time);
 437
 438   // Use a real (non-debug) log to facilitate troubleshooting in the wild.
 439   VLOG(2) << "HttpBridge::OnURLFetchComplete for: "
 440           << fetch_state_.url_poster->GetURL().spec();
 441   VLOG(1) << "HttpBridge received response code: "
 442           << fetch_state_.http_response_code;
 443
 444   source->GetResponseAsString(&fetch_state_.response_content);
 445   fetch_state_.response_headers = source->GetResponseHeaders();
 446   UpdateNetworkTime();
 447
 448   int64 compressed_content_length = fetch_state_.response_content.size();
 449   int64 original_content_length = compressed_content_length;
 450   if (fetch_state_.response_headers &&
 451       fetch_state_.response_headers->HasHeaderValue("content-encoding",
 452                                                     "gzip")) {
 453     compressed_content_length =
 454         fetch_state_.response_headers->GetContentLength();
 455   }
 456   RecordSyncResponseContentLengthHistograms(compressed_content_length,
 457                                             original_content_length);
 458
 459   // End of the line for url_poster_. It lives only on the IO loop.
 460   // We defer deletion because we're inside a callback from a component of the
 461   // URLFetcher, so it seems most natural / "polite" to let the stack unwind.
 462   base::MessageLoop::current()->DeleteSoon(FROM_HERE, fetch_state_.url_poster);
 463   fetch_state_.url_poster = NULL;
 464
 465   // Wake the blocked syncer thread in MakeSynchronousPost.
 466   // WARNING: DONT DO ANYTHING AFTER THIS CALL! |this| may be deleted!
 467   http_post_completed_.Signal();
 468 }
 469
 470 void HttpBridge::OnURLFetchDownloadProgress(const net::URLFetcher* source,
 471                                             int64 current, int64 total) {
 472   DCHECK(network_task_runner_->BelongsToCurrentThread());
 473   // Reset the delay when forward progress is made.
 474   base::AutoLock lock(fetch_state_lock_);
 475   if (fetch_state_.http_request_timeout_timer.get())
 476     fetch_state_.http_request_timeout_timer->Reset();
 477 }
 478
 479 void HttpBridge::OnURLFetchUploadProgress(const net::URLFetcher* source,
 480                                           int64 current, int64 total) {
 481   DCHECK(network_task_runner_->BelongsToCurrentThread());
 482   // Reset the delay when forward progress is made.
 483   base::AutoLock lock(fetch_state_lock_);
 484   if (fetch_state_.http_request_timeout_timer.get())
 485     fetch_state_.http_request_timeout_timer->Reset();
 486 }
 487
 488 void HttpBridge::OnURLFetchTimedOut() {
 489   DCHECK(network_task_runner_->BelongsToCurrentThread());
 490
 491   base::AutoLock lock(fetch_state_lock_);
 492   if (!fetch_state_.url_poster)
 493     return;
 494
 495   LogTimeout(true);
 496   DVLOG(1) << "Sync url fetch timed out. Canceling.";
 497
 498   fetch_state_.end_time = base::Time::Now();
 499   fetch_state_.request_completed = true;
 500   fetch_state_.request_succeeded = false;
 501   fetch_state_.http_response_code = -1;
 502   fetch_state_.error_code = net::URLRequestStatus::FAILED;
 503
 504   // This method is called by the timer, not the url fetcher implementation,
 505   // so it's safe to delete the fetcher here.
 506   delete fetch_state_.url_poster;
 507   fetch_state_.url_poster = NULL;
 508
 509   // Timer is smart enough to handle being deleted as part of the invoked task.
 510   fetch_state_.http_request_timeout_timer.reset();
 511
 512   // Wake the blocked syncer thread in MakeSynchronousPost.
 513   // WARNING: DONT DO ANYTHING AFTER THIS CALL! |this| may be deleted!
 514   http_post_completed_.Signal();
 515 }
 516
 517 net::URLRequestContextGetter* HttpBridge::GetRequestContextGetterForTest()
 518     const {
 519   base::AutoLock lock(fetch_state_lock_);
 520   return request_context_getter_.get();
 521 }
 522
 523 void HttpBridge::UpdateNetworkTime() {
 524   std::string sane_time_str;
 525   if (!fetch_state_.request_succeeded || fetch_state_.start_time.is_null() ||
 526       fetch_state_.end_time < fetch_state_.start_time ||
 527       !fetch_state_.response_headers ||
 528       !fetch_state_.response_headers->EnumerateHeader(NULL, "Sane-Time-Millis",
 529                                                       &sane_time_str)) {
 530     return;
 531   }
 532
 533   int64 sane_time_ms = 0;
 534   if (base::StringToInt64(sane_time_str, &sane_time_ms)) {
 535     network_time_update_callback_.Run(
 536         base::Time::FromJsTime(sane_time_ms),
 537         base::TimeDelta::FromMilliseconds(1),
 538         fetch_state_.end_time - fetch_state_.start_time);
 539   }
 540 }
 541
 542 }  // namespace syncer