Make resource throttles and AsyncResourceHandler add events to NetLog

when they block a request.  This is aimed at making issues easier to
debug when a delegate defers an request for significant periods of time.

Also display that information in about:net-internals when a request is
already active and blocked on a delegate.

BUG=94920

Review URL: https://codereview.chromium.org/25108004

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@238746 0039d316-1c4b-4281-b951-d872f2087c98

3 files changed, 67 insertions, 61 deletions

diff --git a/net/url_request/url_request.cc b/net/url_request/url_request.cc
index 2e4ec57..6b01247 100644
--- a/net/url_request/url_request.cc
+++ b/net/url_request/url_request.cc
@@ -219,7 +219,7 @@ URLRequest::URLRequest(const GURL& url,
       priority_(priority),
       identifier_(GenerateURLRequestIdentifier()),
       calling_delegate_(false),
-      delegate_info_usage_(DELEGATE_INFO_DEBUG_ONLY),
+      use_blocked_by_as_load_param_(false),
       before_request_callback_(base::Bind(&URLRequest::BeforeRequestComplete,
                                           base::Unretained(this))),
       has_notified_completion_(false),
@@ -347,13 +347,13 @@ bool URLRequest::GetFullRequestHeaders(HttpRequestHeaders* headers) const {
 }
 
 LoadStateWithParam URLRequest::GetLoadState() const {
-  // The delegate_info_.empty() check allows |this| to report it's blocked on
-  // a delegate before it has been started.
-  if (calling_delegate_ || !delegate_info_.empty()) {
+  // The !blocked_by_.empty() check allows |this| to report it's blocked on a
+  // delegate before it has been started.
+  if (calling_delegate_ || !blocked_by_.empty()) {
     return LoadStateWithParam(
         LOAD_STATE_WAITING_FOR_DELEGATE,
-        delegate_info_usage_ == DELEGATE_INFO_DISPLAY_TO_USER ?
-            UTF8ToUTF16(delegate_info_) : base::string16());
+        use_blocked_by_as_load_param_ ? UTF8ToUTF16(blocked_by_) :
+                                        base::string16());
   }
   return LoadStateWithParam(job_.get() ? job_->GetLoadState() : LOAD_STATE_IDLE,
                             base::string16());
@@ -378,8 +378,8 @@ base::Value* URLRequest::GetStateAsValue() const {
   dict->SetInteger("load_state", load_state.state);
   if (!load_state.param.empty())
     dict->SetString("load_state_param", load_state.param);
-  if (!delegate_info_.empty())
-    dict->SetString("delegate_info", delegate_info_);
+  if (!blocked_by_.empty())
+    dict->SetString("delegate_info", blocked_by_);
 
   dict->SetString("method", method_);
   dict->SetBoolean("has_upload", has_upload());
@@ -407,25 +407,35 @@ base::Value* URLRequest::GetStateAsValue() const {
   return dict;
 }
 
-void URLRequest::SetDelegateInfo(const char* delegate_info,
-                                 DelegateInfoUsage delegate_info_usage) {
-  // Only log delegate information to NetLog during startup and certain
-  // deferring calls to delegates.  For all reads but the first, delegate info
-  // is currently ignored.
+void URLRequest::LogBlockedBy(const char* blocked_by) {
+  DCHECK(blocked_by);
+  DCHECK_GT(strlen(blocked_by), 0u);
+
+  // Only log information to NetLog during startup and certain deferring calls
+  // to delegates.  For all reads but the first, do nothing.
   if (!calling_delegate_ && !response_info_.request_time.is_null())
     return;
 
-  if (!delegate_info_.empty()) {
-    delegate_info_.clear();
-    net_log_.EndEvent(NetLog::TYPE_DELEGATE_INFO);
-  }
-  if (delegate_info) {
-    delegate_info_ = delegate_info;
-    delegate_info_usage_ = delegate_info_usage;
-    net_log_.BeginEvent(
-        NetLog::TYPE_DELEGATE_INFO,
-        NetLog::StringCallback("delegate_info", &delegate_info_));
-  }
+  LogUnblocked();
+  blocked_by_ = blocked_by;
+  use_blocked_by_as_load_param_ = false;
+
+  net_log_.BeginEvent(
+      NetLog::TYPE_DELEGATE_INFO,
+      NetLog::StringCallback("delegate_info", &blocked_by_));
+}
+
+void URLRequest::LogAndReportBlockedBy(const char* source) {
+  LogBlockedBy(source);
+  use_blocked_by_as_load_param_ = true;
+}
+
+void URLRequest::LogUnblocked() {
+  if (blocked_by_.empty())
+    return;
+
+  net_log_.EndEvent(NetLog::TYPE_DELEGATE_INFO);
+  blocked_by_.clear();
 }
 
 UploadProgress URLRequest::GetUploadProgress() const {
@@ -593,9 +603,9 @@ void URLRequest::set_delegate(Delegate* delegate) {
 
 void URLRequest::Start() {
   DCHECK_EQ(network_delegate_, context_->network_delegate());
-  // Anything that set delegate information before start should have cleaned up
-  // after itself.
-  DCHECK(delegate_info_.empty());
+  // Anything that sets |blocked_by_| before start should have cleaned up after
+  // itself.
+  DCHECK(blocked_by_.empty());
 
   g_url_requests_started = true;
   response_info_.request_time = base::Time::Now();
@@ -715,7 +725,7 @@ void URLRequest::DoCancel(int error, const SSLInfo& ssl_info) {
   DCHECK(error < 0);
   // If cancelled while calling a delegate, clear delegate info.
   if (calling_delegate_) {
-    SetDelegateInfo(NULL, DELEGATE_INFO_DEBUG_ONLY);
+    LogUnblocked();
     OnCallToDelegateComplete();
   }
 
@@ -1162,14 +1172,14 @@ void URLRequest::NotifyRequestCompleted() {
 
 void URLRequest::OnCallToDelegate() {
   DCHECK(!calling_delegate_);
-  DCHECK(delegate_info_.empty());
+  DCHECK(blocked_by_.empty());
   calling_delegate_ = true;
   net_log_.BeginEvent(NetLog::TYPE_URL_REQUEST_DELEGATE);
 }
 
 void URLRequest::OnCallToDelegateComplete() {
-  // Delegates should clear their info when it becomes outdated.
-  DCHECK(delegate_info_.empty());
+  // This should have been cleared before resuming the request.
+  DCHECK(blocked_by_.empty());
   if (!calling_delegate_)
     return;
   calling_delegate_ = false;
diff --git a/net/url_request/url_request.h b/net/url_request/url_request.h
index 606653c..84f5050 100644
--- a/net/url_request/url_request.h
+++ b/net/url_request/url_request.h
@@ -135,15 +135,6 @@ class NET_EXPORT URLRequest : NON_EXPORTED_BASE(public base::NonThreadSafe),
     NEVER_CLEAR_REFERRER,
   };
 
-  // Used with SetDelegateInfo to indicate how the string should be used.
-  // DELEGATE_INFO_DEBUG_ONLY indicates it should only be used when logged to
-  // NetLog, while DELEGATE_INFO_DISPLAY_TO_USER indicates it should also be
-  // returned by calls to GetLoadState for display to the user.
-  enum DelegateInfoUsage {
-    DELEGATE_INFO_DEBUG_ONLY,
-    DELEGATE_INFO_DISPLAY_TO_USER,
-  };
-
   // This class handles network interception.  Use with
   // (Un)RegisterRequestInterceptor.
   class NET_EXPORT Interceptor {
@@ -447,23 +438,31 @@ class NET_EXPORT URLRequest : NON_EXPORTED_BASE(public base::NonThreadSafe),
   // 2. The OnResponseStarted callback is currently running or has run.
   bool GetFullRequestHeaders(HttpRequestHeaders* headers) const;
 
-  // Returns the current load state for the request. |param| is an optional
-  // parameter describing details related to the load state. Not all load states
-  // have a parameter.
+  // Returns the current load state for the request. The returned value's
+  // |param| field is an optional parameter describing details related to the
+  // load state. Not all load states have a parameter.
   LoadStateWithParam GetLoadState() const;
 
   // Returns a partial representation of the request's state as a value, for
   // debugging.  Caller takes ownership of returned value.
   base::Value* GetStateAsValue() const;
 
-  // Logs information about the delegate currently blocking the request.
-  // The delegate info must be cleared by sending NULL before resuming a
-  // request.  |delegate_info| will be copied as needed.  |delegate_info_usage|
-  // is used to indicate whether the value should be returned in the param field
-  // of GetLoadState.  |delegate_info_usage_| is ignored when |delegate_info| is
-  // NULL.
-  void SetDelegateInfo(const char* delegate_info,
-                       DelegateInfoUsage delegate_info_usage);
+  // Logs information about the what external object currently blocking the
+  // request.  LogUnblocked must be called before resuming the request.  This
+  // can be called multiple times in a row either with or without calling
+  // LogUnblocked between calls.  |blocked_by| must not be NULL or have length
+  // 0.
+  void LogBlockedBy(const char* blocked_by);
+
+  // Just like LogBlockedBy, but also makes GetLoadState return source as the
+  // |param| in the value returned by GetLoadState.  Calling LogUnblocked or
+  // LogBlockedBy will clear the load param.  |blocked_by| must not be NULL or
+  // have length 0.
+  void LogAndReportBlockedBy(const char* blocked_by);
+
+  // Logs that the request is no longer blocked by the last caller to
+  // LogBlockedBy.
+  void LogUnblocked();
 
   // Returns the current upload progress in bytes. When the upload data is
   // chunked, size is set to zero, but position will not be.
@@ -851,10 +850,10 @@ class NET_EXPORT URLRequest : NON_EXPORTED_BASE(public base::NonThreadSafe),
   // for the URL request or network delegate to resume it.
   bool calling_delegate_;
 
-  // An optional parameter that provides additional information about the
-  // delegate |this| is currently blocked on.
-  std::string delegate_info_;
-  DelegateInfoUsage delegate_info_usage_;
+  // An optional parameter that provides additional information about what
+  // |this| is currently being blocked by.
+  std::string blocked_by_;
+  bool use_blocked_by_as_load_param_;
 
   base::debug::LeakTracker<URLRequest> leak_tracker_;
 
diff --git a/net/url_request/url_request_unittest.cc b/net/url_request/url_request_unittest.cc
index 6b53b41..d22d24f 100644
--- a/net/url_request/url_request_unittest.cc
+++ b/net/url_request/url_request_unittest.cc
@@ -3843,8 +3843,7 @@ class AsyncDelegateLogger : public base::RefCounted<AsyncDelegateLogger> {
   ~AsyncDelegateLogger() {}
 
   void Start() {
-    url_request_->SetDelegateInfo(kFirstDelegateInfo,
-                                  URLRequest::DELEGATE_INFO_DEBUG_ONLY);
+    url_request_->LogBlockedBy(kFirstDelegateInfo);
     LoadStateWithParam load_state = url_request_->GetLoadState();
     EXPECT_EQ(expected_first_load_state_, load_state.state);
     EXPECT_NE(ASCIIToUTF16(kFirstDelegateInfo), load_state.param);
@@ -3854,8 +3853,7 @@ class AsyncDelegateLogger : public base::RefCounted<AsyncDelegateLogger> {
   }
 
   void LogSecondDelegate() {
-    url_request_->SetDelegateInfo(kSecondDelegateInfo,
-                                  URLRequest::DELEGATE_INFO_DISPLAY_TO_USER);
+    url_request_->LogAndReportBlockedBy(kSecondDelegateInfo);
     LoadStateWithParam load_state = url_request_->GetLoadState();
     EXPECT_EQ(expected_second_load_state_, load_state.state);
     if (expected_second_load_state_ == LOAD_STATE_WAITING_FOR_DELEGATE) {
@@ -3869,8 +3867,7 @@ class AsyncDelegateLogger : public base::RefCounted<AsyncDelegateLogger> {
   }
 
   void LogComplete() {
-    url_request_->SetDelegateInfo(
-        NULL, URLRequest::DELEGATE_INFO_DISPLAY_TO_USER);
+    url_request_->LogUnblocked();
     LoadStateWithParam load_state = url_request_->GetLoadState();
     EXPECT_EQ(expected_third_load_state_, load_state.state);
     if (expected_second_load_state_ == LOAD_STATE_WAITING_FOR_DELEGATE)