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/histogram_macros.h"
   9 #include "base/strings/string_number_conversions.h"
  10 #include "base/strings/stringprintf.h"
  11 #include "net/base/load_flags.h"
  12 #include "net/base/net_errors.h"
  13 #include "net/http/http_cache.h"
  14 #include "net/http/http_network_layer.h"
  15 #include "net/http/http_request_headers.h"
  16 #include "net/http/http_response_headers.h"
  17 #include "net/url_request/static_http_user_agent_settings.h"
  18 #include "net/url_request/url_fetcher.h"
  19 #include "net/url_request/url_request_context.h"
  20 #include "net/url_request/url_request_job_factory_impl.h"
  21 #include "net/url_request/url_request_status.h"
  22 #include "sync/internal_api/public/base/cancelation_signal.h"
  23
  24 namespace syncer {
  25
  26 namespace {
  27
  28 // It's possible for an http request to be silently stalled. We set a time
  29 // limit for all http requests, beyond which the request is cancelled and
  30 // treated as a transient failure.
  31 const int kMaxHttpRequestTimeSeconds = 60 * 5;  // 5 minutes.
  32
  33 // Helper method for logging timeouts via UMA.
  34 void LogTimeout(bool timed_out) {
  35   UMA_HISTOGRAM_BOOLEAN("Sync.URLFetchTimedOut", timed_out);
  36 }
  37
  38 }  // namespace
  39
  40 HttpBridgeFactory::HttpBridgeFactory(
  41     const scoped_refptr<net::URLRequestContextGetter>& request_context_getter,
  42     const NetworkTimeUpdateCallback& network_time_update_callback,
  43     CancelationSignal* cancelation_signal)
  44     : request_context_getter_(request_context_getter),
  45       network_time_update_callback_(network_time_update_callback),
  46       cancelation_signal_(cancelation_signal) {
  47   // Registration should never fail.  This should happen on the UI thread during
  48   // init.  It would be impossible for a shutdown to have been requested at this
  49   // point.
  50   bool result = cancelation_signal_->TryRegisterHandler(this);
  51   DCHECK(result);
  52 }
  53
  54 HttpBridgeFactory::~HttpBridgeFactory() {
  55   cancelation_signal_->UnregisterHandler(this);
  56 }
  57
  58 void HttpBridgeFactory::Init(const std::string& user_agent) {
  59   user_agent_ = user_agent;
  60 }
  61
  62 HttpPostProviderInterface* HttpBridgeFactory::Create() {
  63   base::AutoLock lock(request_context_getter_lock_);
  64
  65   // If we've been asked to shut down (something which may happen asynchronously
  66   // and at pretty much any time), then we won't have a request_context_getter_.
  67   // Some external mechanism must ensure that this function is not called after
  68   // we've been asked to shut down.
  69   CHECK(request_context_getter_.get());
  70
  71   scoped_refptr<HttpBridge> http = new HttpBridge(
  72       user_agent_, request_context_getter_, network_time_update_callback_);
  73   http->AddRef();
  74   return http.get();
  75 }
  76
  77 void HttpBridgeFactory::Destroy(HttpPostProviderInterface* http) {
  78   static_cast<HttpBridge*>(http)->Release();
  79 }
  80
  81 void HttpBridgeFactory::OnSignalReceived() {
  82   base::AutoLock lock(request_context_getter_lock_);
  83   // Release |request_context_getter_| as soon as possible so that it
  84   // is destroyed in the right order on its network task runner.
  85   request_context_getter_ = NULL;
  86 }
  87
  88 HttpBridge::URLFetchState::URLFetchState()
  89     : url_poster(NULL),
  90       aborted(false),
  91       request_completed(false),
  92       request_succeeded(false),
  93       http_response_code(-1),
  94       error_code(-1) {
  95 }
  96 HttpBridge::URLFetchState::~URLFetchState() {}
  97
  98 HttpBridge::HttpBridge(
  99     const std::string& user_agent,
 100     const scoped_refptr<net::URLRequestContextGetter>& context_getter,
 101     const NetworkTimeUpdateCallback& network_time_update_callback)
 102     : created_on_loop_(base::MessageLoop::current()),
 103       user_agent_(user_agent),
 104       http_post_completed_(false, false),
 105       request_context_getter_(context_getter),
 106       network_task_runner_(request_context_getter_->GetNetworkTaskRunner()),
 107       network_time_update_callback_(network_time_update_callback) {
 108 }
 109
 110 HttpBridge::~HttpBridge() {
 111 }
 112
 113 void HttpBridge::SetExtraRequestHeaders(const char * headers) {
 114   DCHECK(extra_headers_.empty())
 115       << "HttpBridge::SetExtraRequestHeaders called twice.";
 116   extra_headers_.assign(headers);
 117 }
 118
 119 void HttpBridge::SetURL(const char* url, int port) {
 120 #if DCHECK_IS_ON()
 121   DCHECK_EQ(base::MessageLoop::current(), created_on_loop_);
 122   {
 123     base::AutoLock lock(fetch_state_lock_);
 124     DCHECK(!fetch_state_.request_completed);
 125   }
 126   DCHECK(url_for_request_.is_empty())
 127       << "HttpBridge::SetURL called more than once?!";
 128 #endif
 129   GURL temp(url);
 130   GURL::Replacements replacements;
 131   std::string port_str = base::IntToString(port);
 132   replacements.SetPort(port_str.c_str(), url::Component(0, port_str.length()));
 133   url_for_request_ = temp.ReplaceComponents(replacements);
 134 }
 135
 136 void HttpBridge::SetPostPayload(const char* content_type,
 137                                 int content_length,
 138                                 const char* content) {
 139 #if DCHECK_IS_ON()
 140   DCHECK_EQ(base::MessageLoop::current(), created_on_loop_);
 141   {
 142     base::AutoLock lock(fetch_state_lock_);
 143     DCHECK(!fetch_state_.request_completed);
 144   }
 145   DCHECK(content_type_.empty()) << "Bridge payload already set.";
 146   DCHECK_GE(content_length, 0) << "Content length < 0";
 147 #endif
 148   content_type_ = content_type;
 149   if (!content || (content_length == 0)) {
 150     DCHECK_EQ(content_length, 0);
 151     request_content_ = " ";  // TODO(timsteele): URLFetcher requires non-empty
 152                              // content for POSTs whereas CURL does not, for now
 153                              // we hack this to support the sync backend.
 154   } else {
 155     request_content_.assign(content, content_length);
 156   }
 157 }
 158
 159 bool HttpBridge::MakeSynchronousPost(int* error_code, int* response_code) {
 160 #if DCHECK_IS_ON()
 161   DCHECK_EQ(base::MessageLoop::current(), created_on_loop_);
 162   {
 163     base::AutoLock lock(fetch_state_lock_);
 164     DCHECK(!fetch_state_.request_completed);
 165   }
 166   DCHECK(url_for_request_.is_valid()) << "Invalid URL for request";
 167   DCHECK(!content_type_.empty()) << "Payload not set";
 168 #endif
 169
 170   if (!network_task_runner_->PostTask(
 171           FROM_HERE,
 172           base::Bind(&HttpBridge::CallMakeAsynchronousPost, this))) {
 173     // This usually happens when we're in a unit test.
 174     LOG(WARNING) << "Could not post CallMakeAsynchronousPost task";
 175     return false;
 176   }
 177
 178   // Block until network request completes or is aborted. See
 179   // OnURLFetchComplete and Abort.
 180   http_post_completed_.Wait();
 181
 182   base::AutoLock lock(fetch_state_lock_);
 183   DCHECK(fetch_state_.request_completed || fetch_state_.aborted);
 184   *error_code = fetch_state_.error_code;
 185   *response_code = fetch_state_.http_response_code;
 186   return fetch_state_.request_succeeded;
 187 }
 188
 189 void HttpBridge::MakeAsynchronousPost() {
 190   DCHECK(network_task_runner_->BelongsToCurrentThread());
 191
 192   base::AutoLock lock(fetch_state_lock_);
 193   DCHECK(!fetch_state_.request_completed);
 194   if (fetch_state_.aborted)
 195     return;
 196
 197   // Start the timer on the network thread (the same thread progress is made
 198   // on, and on which the url fetcher lives).
 199   DCHECK(!fetch_state_.http_request_timeout_timer.get());
 200   fetch_state_.http_request_timeout_timer.reset(new base::Timer(false, false));
 201   fetch_state_.http_request_timeout_timer->Start(
 202       FROM_HERE, base::TimeDelta::FromSeconds(kMaxHttpRequestTimeSeconds),
 203       base::Bind(&HttpBridge::OnURLFetchTimedOut, this));
 204
 205   DCHECK(request_context_getter_.get());
 206   fetch_state_.url_poster =
 207       net::URLFetcher::Create(url_for_request_, net::URLFetcher::POST, this)
 208           .release();
 209   fetch_state_.url_poster->SetRequestContext(request_context_getter_.get());
 210   fetch_state_.url_poster->SetUploadData(content_type_, request_content_);
 211   fetch_state_.url_poster->SetExtraRequestHeaders(extra_headers_);
 212   fetch_state_.url_poster->AddExtraRequestHeader(base::StringPrintf(
 213       "%s: %s", net::HttpRequestHeaders::kUserAgent, user_agent_.c_str()));
 214   fetch_state_.url_poster->SetLoadFlags(net::LOAD_BYPASS_CACHE |
 215                                         net::LOAD_DISABLE_CACHE |
 216                                         net::LOAD_DO_NOT_SAVE_COOKIES |
 217                                         net::LOAD_DO_NOT_SEND_COOKIES);
 218   fetch_state_.start_time = base::Time::Now();
 219
 220   fetch_state_.url_poster->Start();
 221 }
 222
 223 int HttpBridge::GetResponseContentLength() const {
 224   DCHECK_EQ(base::MessageLoop::current(), created_on_loop_);
 225   base::AutoLock lock(fetch_state_lock_);
 226   DCHECK(fetch_state_.request_completed);
 227   return fetch_state_.response_content.size();
 228 }
 229
 230 const char* HttpBridge::GetResponseContent() const {
 231   DCHECK_EQ(base::MessageLoop::current(), created_on_loop_);
 232   base::AutoLock lock(fetch_state_lock_);
 233   DCHECK(fetch_state_.request_completed);
 234   return fetch_state_.response_content.data();
 235 }
 236
 237 const std::string HttpBridge::GetResponseHeaderValue(
 238     const std::string& name) const {
 239
 240   DCHECK_EQ(base::MessageLoop::current(), created_on_loop_);
 241   base::AutoLock lock(fetch_state_lock_);
 242   DCHECK(fetch_state_.request_completed);
 243
 244   std::string value;
 245   fetch_state_.response_headers->EnumerateHeader(NULL, name, &value);
 246   return value;
 247 }
 248
 249 void HttpBridge::Abort() {
 250   base::AutoLock lock(fetch_state_lock_);
 251
 252   // Release |request_context_getter_| as soon as possible so that it is
 253   // destroyed in the right order on its network task runner.
 254   request_context_getter_ = NULL;
 255
 256   DCHECK(!fetch_state_.aborted);
 257   if (fetch_state_.aborted || fetch_state_.request_completed)
 258     return;
 259
 260   fetch_state_.aborted = true;
 261   if (!network_task_runner_->PostTask(
 262           FROM_HERE,
 263           base::Bind(&HttpBridge::DestroyURLFetcherOnIOThread, this,
 264                      fetch_state_.url_poster,
 265                      fetch_state_.http_request_timeout_timer.release()))) {
 266     // Madness ensues.
 267     NOTREACHED() << "Could not post task to delete URLFetcher";
 268   }
 269
 270   fetch_state_.url_poster = NULL;
 271   fetch_state_.error_code = net::ERR_ABORTED;
 272   http_post_completed_.Signal();
 273 }
 274
 275 void HttpBridge::DestroyURLFetcherOnIOThread(
 276     net::URLFetcher* fetcher,
 277     base::Timer* fetch_timer) {
 278   DCHECK(network_task_runner_->BelongsToCurrentThread());
 279   if (fetch_timer)
 280     delete fetch_timer;
 281   delete fetcher;
 282 }
 283
 284 void HttpBridge::OnURLFetchComplete(const net::URLFetcher* source) {
 285   DCHECK(network_task_runner_->BelongsToCurrentThread());
 286
 287   base::AutoLock lock(fetch_state_lock_);
 288
 289   // Stop the request timer now that the request completed.
 290   if (fetch_state_.http_request_timeout_timer.get())
 291     fetch_state_.http_request_timeout_timer.reset();
 292
 293   if (fetch_state_.aborted)
 294     return;
 295
 296   fetch_state_.end_time = base::Time::Now();
 297   fetch_state_.request_completed = true;
 298   fetch_state_.request_succeeded =
 299       (net::URLRequestStatus::SUCCESS == source->GetStatus().status());
 300   fetch_state_.http_response_code = source->GetResponseCode();
 301   fetch_state_.error_code = source->GetStatus().error();
 302
 303   if (fetch_state_.request_succeeded)
 304     LogTimeout(false);
 305   UMA_HISTOGRAM_LONG_TIMES("Sync.URLFetchTime",
 306                            fetch_state_.end_time - fetch_state_.start_time);
 307
 308   // Use a real (non-debug) log to facilitate troubleshooting in the wild.
 309   VLOG(2) << "HttpBridge::OnURLFetchComplete for: "
 310           << fetch_state_.url_poster->GetURL().spec();
 311   VLOG(1) << "HttpBridge received response code: "
 312           << fetch_state_.http_response_code;
 313
 314   source->GetResponseAsString(&fetch_state_.response_content);
 315   fetch_state_.response_headers = source->GetResponseHeaders();
 316   UpdateNetworkTime();
 317
 318   // End of the line for url_poster_. It lives only on the IO loop.
 319   // We defer deletion because we're inside a callback from a component of the
 320   // URLFetcher, so it seems most natural / "polite" to let the stack unwind.
 321   base::MessageLoop::current()->DeleteSoon(FROM_HERE, fetch_state_.url_poster);
 322   fetch_state_.url_poster = NULL;
 323
 324   // Wake the blocked syncer thread in MakeSynchronousPost.
 325   // WARNING: DONT DO ANYTHING AFTER THIS CALL! |this| may be deleted!
 326   http_post_completed_.Signal();
 327 }
 328
 329 void HttpBridge::OnURLFetchDownloadProgress(const net::URLFetcher* source,
 330                                             int64 current, int64 total) {
 331   DCHECK(network_task_runner_->BelongsToCurrentThread());
 332   // Reset the delay when forward progress is made.
 333   base::AutoLock lock(fetch_state_lock_);
 334   if (fetch_state_.http_request_timeout_timer.get())
 335     fetch_state_.http_request_timeout_timer->Reset();
 336 }
 337
 338 void HttpBridge::OnURLFetchUploadProgress(const net::URLFetcher* source,
 339                                           int64 current, int64 total) {
 340   DCHECK(network_task_runner_->BelongsToCurrentThread());
 341   // Reset the delay when forward progress is made.
 342   base::AutoLock lock(fetch_state_lock_);
 343   if (fetch_state_.http_request_timeout_timer.get())
 344     fetch_state_.http_request_timeout_timer->Reset();
 345 }
 346
 347 void HttpBridge::OnURLFetchTimedOut() {
 348   DCHECK(network_task_runner_->BelongsToCurrentThread());
 349
 350   base::AutoLock lock(fetch_state_lock_);
 351   if (!fetch_state_.url_poster)
 352     return;
 353
 354   LogTimeout(true);
 355   DVLOG(1) << "Sync url fetch timed out. Canceling.";
 356
 357   fetch_state_.end_time = base::Time::Now();
 358   fetch_state_.request_completed = true;
 359   fetch_state_.request_succeeded = false;
 360   fetch_state_.http_response_code = -1;
 361   fetch_state_.error_code = net::URLRequestStatus::FAILED;
 362
 363   // This method is called by the timer, not the url fetcher implementation,
 364   // so it's safe to delete the fetcher here.
 365   delete fetch_state_.url_poster;
 366   fetch_state_.url_poster = NULL;
 367
 368   // Timer is smart enough to handle being deleted as part of the invoked task.
 369   fetch_state_.http_request_timeout_timer.reset();
 370
 371   // Wake the blocked syncer thread in MakeSynchronousPost.
 372   // WARNING: DONT DO ANYTHING AFTER THIS CALL! |this| may be deleted!
 373   http_post_completed_.Signal();
 374 }
 375
 376 net::URLRequestContextGetter* HttpBridge::GetRequestContextGetterForTest()
 377     const {
 378   base::AutoLock lock(fetch_state_lock_);
 379   return request_context_getter_.get();
 380 }
 381
 382 void HttpBridge::UpdateNetworkTime() {
 383   std::string sane_time_str;
 384   if (!fetch_state_.request_succeeded || fetch_state_.start_time.is_null() ||
 385       fetch_state_.end_time < fetch_state_.start_time ||
 386       !fetch_state_.response_headers ||
 387       !fetch_state_.response_headers->EnumerateHeader(NULL, "Sane-Time-Millis",
 388                                                       &sane_time_str)) {
 389     return;
 390   }
 391
 392   int64 sane_time_ms = 0;
 393   if (base::StringToInt64(sane_time_str, &sane_time_ms)) {
 394     network_time_update_callback_.Run(
 395         base::Time::FromJsTime(sane_time_ms),
 396         base::TimeDelta::FromMilliseconds(1),
 397         fetch_state_.end_time - fetch_state_.start_time);
 398   }
 399 }
 400
 401 }  // namespace syncer