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