diff options
author | zea <zea@chromium.org> | 2014-12-17 19:12:10 -0800 |
---|---|---|
committer | Commit bot <commit-bot@chromium.org> | 2014-12-18 03:12:36 +0000 |
commit | b4104348712f14b49b6a5c7c6c857a9543a4fb5d (patch) | |
tree | 4f3c2fdbc1abbe3693425297c51c39cf05b65e83 /sync | |
parent | 42b70b4a7f7a60375cb1ac7d89a1e1230a959084 (diff) | |
download | chromium_src-b4104348712f14b49b6a5c7c6c857a9543a4fb5d.zip chromium_src-b4104348712f14b49b6a5c7c6c857a9543a4fb5d.tar.gz chromium_src-b4104348712f14b49b6a5c7c6c857a9543a4fb5d.tar.bz2 |
[Sync] Add url fetch timeout logic
It's possible for a url fetch to stall silently. This patch adds a 5 minute
timeout mechanism which will cancel the url fetch when triggered, resulting
in a retry with backoff. Also add histograms to track how often this is
getting hit and how long url fetches take to complete in general.
BUG=427972
Review URL: https://codereview.chromium.org/780893003
Cr-Commit-Position: refs/heads/master@{#308939}
Diffstat (limited to 'sync')
-rw-r--r-- | sync/internal_api/http_bridge.cc | 107 | ||||
-rw-r--r-- | sync/internal_api/public/http_bridge.h | 15 |
2 files changed, 113 insertions, 9 deletions
diff --git a/sync/internal_api/http_bridge.cc b/sync/internal_api/http_bridge.cc index c9db173c..e785d02 100644 --- a/sync/internal_api/http_bridge.cc +++ b/sync/internal_api/http_bridge.cc @@ -5,6 +5,7 @@ #include "sync/internal_api/public/http_bridge.h" #include "base/message_loop/message_loop.h" +#include "base/metrics/histogram_macros.h" #include "base/strings/string_number_conversions.h" #include "net/base/load_flags.h" #include "net/base/net_errors.h" @@ -21,6 +22,20 @@ namespace syncer { +namespace { + +// It's possible for an http request to be silently stalled. We set a time +// limit for all http requests, beyond which the request is cancelled and +// treated as a transient failure. +const int kMaxHttpRequestTimeSeconds = 60 * 5; // 5 minutes. + +// Helper method for logging timeouts via UMA. +void LogTimeout(bool timed_out) { + UMA_HISTOGRAM_BOOLEAN("Sync.URLFetchTimedOut", timed_out); +} + +} // namespace + HttpBridge::RequestContextGetter::RequestContextGetter( net::URLRequestContextGetter* baseline_context_getter, const std::string& user_agent) @@ -171,12 +186,14 @@ HttpBridge::RequestContext::~RequestContext() { delete http_transaction_factory(); } -HttpBridge::URLFetchState::URLFetchState() : url_poster(NULL), - aborted(false), - request_completed(false), - request_succeeded(false), - http_response_code(-1), - error_code(-1) {} +HttpBridge::URLFetchState::URLFetchState() + : url_poster(NULL), + aborted(false), + request_completed(false), + request_succeeded(false), + http_response_code(-1), + error_code(-1) { +} HttpBridge::URLFetchState::~URLFetchState() {} HttpBridge::HttpBridge( @@ -271,11 +288,20 @@ bool HttpBridge::MakeSynchronousPost(int* error_code, int* response_code) { void HttpBridge::MakeAsynchronousPost() { DCHECK(network_task_runner_->BelongsToCurrentThread()); + base::AutoLock lock(fetch_state_lock_); DCHECK(!fetch_state_.request_completed); if (fetch_state_.aborted) return; + // Start the timer on the network thread (the same thread progress is made + // on, and on which the url fetcher lives). + DCHECK(!fetch_state_.http_request_timeout_timer.get()); + fetch_state_.http_request_timeout_timer.reset(new base::Timer(false, false)); + fetch_state_.http_request_timeout_timer->Start( + FROM_HERE, base::TimeDelta::FromSeconds(kMaxHttpRequestTimeSeconds), + base::Bind(&HttpBridge::OnURLFetchTimedOut, this)); + DCHECK(context_getter_for_request_.get()); fetch_state_.url_poster = net::URLFetcher::Create( url_for_request_, net::URLFetcher::POST, this); @@ -284,6 +310,7 @@ void HttpBridge::MakeAsynchronousPost() { fetch_state_.url_poster->SetExtraRequestHeaders(extra_headers_); fetch_state_.url_poster->SetLoadFlags(net::LOAD_DO_NOT_SEND_COOKIES); fetch_state_.start_time = base::Time::Now(); + fetch_state_.url_poster->Start(); } @@ -328,7 +355,8 @@ void HttpBridge::Abort() { if (!network_task_runner_->PostTask( FROM_HERE, base::Bind(&HttpBridge::DestroyURLFetcherOnIOThread, this, - fetch_state_.url_poster))) { + fetch_state_.url_poster, + fetch_state_.http_request_timeout_timer.release()))) { // Madness ensues. NOTREACHED() << "Could not post task to delete URLFetcher"; } @@ -338,14 +366,24 @@ void HttpBridge::Abort() { http_post_completed_.Signal(); } -void HttpBridge::DestroyURLFetcherOnIOThread(net::URLFetcher* fetcher) { +void HttpBridge::DestroyURLFetcherOnIOThread( + net::URLFetcher* fetcher, + base::Timer* fetch_timer) { DCHECK(network_task_runner_->BelongsToCurrentThread()); + if (fetch_timer) + delete fetch_timer; delete fetcher; } void HttpBridge::OnURLFetchComplete(const net::URLFetcher* source) { DCHECK(network_task_runner_->BelongsToCurrentThread()); + base::AutoLock lock(fetch_state_lock_); + + // Stop the request timer now that the request completed. + if (fetch_state_.http_request_timeout_timer.get()) + fetch_state_.http_request_timeout_timer.reset(); + if (fetch_state_.aborted) return; @@ -356,6 +394,11 @@ void HttpBridge::OnURLFetchComplete(const net::URLFetcher* source) { fetch_state_.http_response_code = source->GetResponseCode(); fetch_state_.error_code = source->GetStatus().error(); + if (fetch_state_.request_succeeded) + LogTimeout(false); + UMA_HISTOGRAM_LONG_TIMES("Sync.URLFetchTime", + fetch_state_.end_time - fetch_state_.start_time); + // Use a real (non-debug) log to facilitate troubleshooting in the wild. VLOG(2) << "HttpBridge::OnURLFetchComplete for: " << fetch_state_.url_poster->GetURL().spec(); @@ -377,6 +420,53 @@ void HttpBridge::OnURLFetchComplete(const net::URLFetcher* source) { http_post_completed_.Signal(); } +void HttpBridge::OnURLFetchDownloadProgress(const net::URLFetcher* source, + int64 current, int64 total) { + DCHECK(network_task_runner_->BelongsToCurrentThread()); + // Reset the delay when forward progress is made. + base::AutoLock lock(fetch_state_lock_); + if (fetch_state_.http_request_timeout_timer.get()) + fetch_state_.http_request_timeout_timer->Reset(); +} + +void HttpBridge::OnURLFetchUploadProgress(const net::URLFetcher* source, + int64 current, int64 total) { + DCHECK(network_task_runner_->BelongsToCurrentThread()); + // Reset the delay when forward progress is made. + base::AutoLock lock(fetch_state_lock_); + if (fetch_state_.http_request_timeout_timer.get()) + fetch_state_.http_request_timeout_timer->Reset(); +} + +void HttpBridge::OnURLFetchTimedOut() { + DCHECK(network_task_runner_->BelongsToCurrentThread()); + + base::AutoLock lock(fetch_state_lock_); + if (!fetch_state_.url_poster) + return; + + LogTimeout(true); + DVLOG(1) << "Sync url fetch timed out. Canceling."; + + fetch_state_.end_time = base::Time::Now(); + fetch_state_.request_completed = true; + fetch_state_.request_succeeded = false; + fetch_state_.http_response_code = -1; + fetch_state_.error_code = net::URLRequestStatus::FAILED; + + // This method is called by the timer, not the url fetcher implementation, + // so it's safe to delete the fetcher here. + delete fetch_state_.url_poster; + fetch_state_.url_poster = NULL; + + // Timer is smart enough to handle being deleted as part of the invoked task. + fetch_state_.http_request_timeout_timer.reset(); + + // Wake the blocked syncer thread in MakeSynchronousPost. + // WARNING: DONT DO ANYTHING AFTER THIS CALL! |this| may be deleted! + http_post_completed_.Signal(); +} + net::URLRequestContextGetter* HttpBridge::GetRequestContextGetterForTest() const { base::AutoLock lock(fetch_state_lock_); @@ -387,6 +477,7 @@ void HttpBridge::UpdateNetworkTime() { std::string sane_time_str; if (!fetch_state_.request_succeeded || fetch_state_.start_time.is_null() || fetch_state_.end_time < fetch_state_.start_time || + !fetch_state_.response_headers || !fetch_state_.response_headers->EnumerateHeader(NULL, "Sane-Time-Millis", &sane_time_str)) { return; diff --git a/sync/internal_api/public/http_bridge.h b/sync/internal_api/public/http_bridge.h index 8b7839a..4e613dd 100644 --- a/sync/internal_api/public/http_bridge.h +++ b/sync/internal_api/public/http_bridge.h @@ -13,6 +13,7 @@ #include "base/memory/ref_counted.h" #include "base/synchronization/lock.h" #include "base/synchronization/waitable_event.h" +#include "base/timer/timer.h" #include "net/url_request/url_fetcher_delegate.h" #include "net/url_request/url_request_context.h" #include "net/url_request/url_request_context_getter.h" @@ -129,6 +130,10 @@ class SYNC_EXPORT_PRIVATE HttpBridge // net::URLFetcherDelegate implementation. void OnURLFetchComplete(const net::URLFetcher* source) override; + void OnURLFetchDownloadProgress(const net::URLFetcher* source, + int64 current, int64 total) override; + void OnURLFetchUploadProgress(const net::URLFetcher* source, + int64 current, int64 total) override; net::URLRequestContextGetter* GetRequestContextGetterForTest() const; @@ -153,10 +158,14 @@ class SYNC_EXPORT_PRIVATE HttpBridge // a reference to |this| is held while flushing any pending fetch completion // callbacks coming from the IO thread en route to finally destroying the // fetcher. - void DestroyURLFetcherOnIOThread(net::URLFetcher* fetcher); + void DestroyURLFetcherOnIOThread(net::URLFetcher* fetcher, + base::Timer* fetch_timer); void UpdateNetworkTime(); + // Helper method to abort the request if we timed out. + void OnURLFetchTimedOut(); + // The message loop of the thread we were created on. This is the thread that // will block on MakeSynchronousPost while the IO thread fetches data from // the network. @@ -202,6 +211,10 @@ class SYNC_EXPORT_PRIVATE HttpBridge int error_code; std::string response_content; scoped_refptr<net::HttpResponseHeaders> response_headers; + + // Timer to ensure http requests aren't stalled. Reset every time upload or + // download progress is made. + scoped_ptr<base::Timer> http_request_timeout_timer; }; // This lock synchronizes use of state involved in the flow to fetch a URL |