[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}

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