Split URL_REQUEST_DELEGATE into per-delegate logs.

Before, one must guess from context which delegate was called:

t=2141 [st=  0] +REQUEST_ALIVE  [dt=301]
                 --> priority = "HIGHEST"
                 --> url = "https://example.com/"
t=2141 [st=  0]    URL_REQUEST_DELEGATE  [dt=1]
t=2142 [st=  1]   +URL_REQUEST_START_JOB  [dt=298]
                   --> load_flags = 18432 (MAIN_FRAME_DEPRECATED | MAYBE_USER_GESTURE)
                   --> method = "GET"
                   --> url = "https://example.com/"
t=2142 [st=  1]      URL_REQUEST_DELEGATE  [dt=0]
t=2142 [st=  1]      HTTP_CACHE_GET_BACKEND  [dt=0]
t=2142 [st=  1]      HTTP_CACHE_OPEN_ENTRY  [dt=0]
                     --> net_error = -2 (ERR_FAILED)

Now it is spelled out explicitly:

t=2141 [st=  0] +REQUEST_ALIVE  [dt=301]
                 --> priority = "HIGHEST"
                 --> url = "https://example.com/"
t=2141 [st=  0]    NETWORK_DELEGATE_BEFORE_URL_REQUEST  [dt=1]
t=2142 [st=  1]   +URL_REQUEST_START_JOB  [dt=298]
                   --> load_flags = 18432 (MAIN_FRAME_DEPRECATED | MAYBE_USER_GESTURE)
                   --> method = "GET"
                   --> url = "https://example.com/"
t=2142 [st=  1]      NETWORK_DELEGATE_BEFORE_START_TRANSACTION  [dt=0]
t=2142 [st=  1]      HTTP_CACHE_GET_BACKEND  [dt=0]
t=2142 [st=  1]      HTTP_CACHE_OPEN_ENTRY  [dt=0]
                     --> net_error = -2 (ERR_FAILED)

(Okay, I cheated and made the "before" example by editting the "after" one, but
whatever.)

Bug: none
Cq-Include-Trybots: master.tryserver.chromium.linux:closure_compilation
Change-Id: Ie5fe7b4405c2389eaece479ff1c93774fe18b8ba
Reviewed-on: https://chromium-review.googlesource.com/1096083Reviewed-by: Matt Menke <mmenke@chromium.org>
Commit-Queue: David Benjamin <davidben@chromium.org>
Cr-Commit-Position: refs/heads/master@{#566632}

chrome/browser/resources/net_internals/source_entry.js

@@ -216,7 +216,11 @@ var SourceEntry = (function() {
         if (this.entries_[0].type == EventType.REQUEST_ALIVE &&
             this.entries_[0].params == undefined) {
           var startIndex = 1;
-          // Skip over delegate events for URL_REQUESTs.
+          // Skip over delegate events for URL_REQUESTs. Note: in newer
+          // versions, URL_REQUEST_DELEGATE has been split into multiple event
+          // types. However, all those versions also include the REQUEST_ALIVE
+          // parameters added in https://crrev.com/441259, so only the
+          // URL_REQUEST_DELEGATE version of this logic is needed.
           for (; startIndex + 1 < this.entries_.length; ++startIndex) {
             var type = this.entries_[startIndex].type;
             if (type != EventType.URL_REQUEST_DELEGATE &&

net/docs/crash-course-in-net-internals.md

@@ -182,14 +182,14 @@ Some things to look for while debugging:
 fun and exciting effects on underway network activity.  Network changes log a
 top level NETWORK_CHANGED event.  Suspend events are currently not logged.
 
-* URL_REQUEST_DELEGATE / DELEGATE_INFO events mean a URL_REQUEST is blocked on a
-URLRequest::Delegate or the NetworkDelegate, which are implemented outside the
-network stack.  A request will sometimes be CANCELED here for reasons known only
-to the delegate.  Or the delegate may cause a hang.  In general, to debug issues
-related to delegates, one needs to figure out which method of which object is
-causing the problem.  The object may be the a NetworkDelegate, a
-ResourceThrottle, a ResourceHandler, the ResourceLoader itself, or the
-ResourceDispatcherHost.
+* URL_REQUEST_DELEGATE_\* / NETWORK_DELEGATE_\* / DELEGATE_INFO events mean a
+URL_REQUEST is blocked on a URLRequest::Delegate or the NetworkDelegate, which
+are implemented outside the network stack.  A request will sometimes be CANCELED
+here for reasons known only to the delegate.  Or the delegate may cause a hang.
+In general, to debug issues related to delegates, one needs to figure out which
+method of which object is causing the problem.  The object may be the a
+NetworkDelegate, a ResourceThrottle, a ResourceHandler, the ResourceLoader
+itself, or the ResourceDispatcherHost.
 
 * Sockets are often reused between requests.  If a request is on a stale
 (reused) socket, what was the previous request that used the socket, how long

net/log/net_log_event_type_list.h

@@ -842,8 +842,16 @@ EVENT_TYPE(URL_REQUEST_START_JOB)
 EVENT_TYPE(URL_REQUEST_REDIRECTED)
 
 // Measures the time between when a net::URLRequest calls a delegate that can
-// block it, and when the delegate allows the request to resume.
-EVENT_TYPE(URL_REQUEST_DELEGATE)
+// block it, and when the delegate allows the request to resume. Each delegate
+// type has a corresponding event type.
+EVENT_TYPE(NETWORK_DELEGATE_AUTH_REQUIRED)
+EVENT_TYPE(NETWORK_DELEGATE_BEFORE_START_TRANSACTION)
+EVENT_TYPE(NETWORK_DELEGATE_BEFORE_URL_REQUEST)
+EVENT_TYPE(NETWORK_DELEGATE_HEADERS_RECEIVED)
+EVENT_TYPE(URL_REQUEST_DELEGATE_CERTIFICATE_REQUESTED)
+EVENT_TYPE(URL_REQUEST_DELEGATE_RECEIVED_REDIRECT)
+EVENT_TYPE(URL_REQUEST_DELEGATE_RESPONSE_STARTED)
+EVENT_TYPE(URL_REQUEST_DELEGATE_SSL_CERTIFICATE_ERROR)
 
 // Logged when a delegate informs the URL_REQUEST of what's currently blocking
 // the request. The parameters attached to the begin event are:

net/url_request/url_request.cc

@@ -530,7 +530,7 @@ void URLRequest::Start() {
   load_timing_info_.request_start = base::TimeTicks::Now();
 
   if (network_delegate_) {
-    OnCallToDelegate();
+    OnCallToDelegate(NetLogEventType::NETWORK_DELEGATE_BEFORE_URL_REQUEST);
     int error = network_delegate_->NotifyBeforeURLRequest(
         this,
         base::BindOnce(&URLRequest::BeforeRequestComplete,
@@ -573,6 +573,7 @@ URLRequest::URLRequest(const GURL& url,
       redirect_limit_(kMaxRedirects),
       priority_(priority),
       identifier_(GenerateURLRequestIdentifier()),
+      delegate_event_type_(NetLogEventType::FAILED),
       calling_delegate_(false),
       use_blocked_by_as_load_param_(false),
       has_notified_completion_(false),
@@ -806,7 +807,7 @@ void URLRequest::NotifyReceivedRedirect(const RedirectInfo& redirect_info,
   if (job) {
     RestartWithJob(job);
   } else {
-    OnCallToDelegate();
+    OnCallToDelegate(NetLogEventType::URL_REQUEST_DELEGATE_RECEIVED_REDIRECT);
     delegate_->OnReceivedRedirect(this, redirect_info, defer_redirect);
     // |this| may be have been destroyed here.
   }
@@ -840,7 +841,7 @@ void URLRequest::NotifyResponseStarted(const URLRequestStatus& status) {
     if (!has_notified_completion_ && !status_.is_success())
       NotifyRequestCompleted();
 
-    OnCallToDelegate();
+    OnCallToDelegate(NetLogEventType::URL_REQUEST_DELEGATE_RESPONSE_STARTED);
     delegate_->OnResponseStarted(this, net_error);
     // Nothing may appear below this line as OnResponseStarted may delete
     // |this|.
@@ -997,7 +998,7 @@ void URLRequest::NotifyAuthRequired(AuthChallengeInfo* auth_info) {
       NetworkDelegate::AUTH_REQUIRED_RESPONSE_NO_ACTION;
   auth_info_ = auth_info;
   if (network_delegate_) {
-    OnCallToDelegate();
+    OnCallToDelegate(NetLogEventType::NETWORK_DELEGATE_AUTH_REQUIRED);
     rv = network_delegate_->NotifyAuthRequired(
         this, *auth_info,
         base::BindOnce(&URLRequest::NotifyAuthRequiredComplete,
@@ -1049,14 +1050,14 @@ void URLRequest::NotifyAuthRequiredComplete(
 void URLRequest::NotifyCertificateRequested(
     SSLCertRequestInfo* cert_request_info) {
   status_ = URLRequestStatus();
-  OnCallToDelegate();
+  OnCallToDelegate(NetLogEventType::URL_REQUEST_DELEGATE_CERTIFICATE_REQUESTED);
   delegate_->OnCertificateRequested(this, cert_request_info);
 }
 
 void URLRequest::NotifySSLCertificateError(const SSLInfo& ssl_info,
                                            bool fatal) {
   status_ = URLRequestStatus();
-  OnCallToDelegate();
+  OnCallToDelegate(NetLogEventType::URL_REQUEST_DELEGATE_SSL_CERTIFICATE_ERROR);
   delegate_->OnSSLCertificateError(this, ssl_info, fatal);
 }
 
@@ -1153,11 +1154,12 @@ void URLRequest::NotifyRequestCompleted() {
 #endif  // BUILDFLAG(ENABLE_REPORTING)
 }
 
-void URLRequest::OnCallToDelegate() {
+void URLRequest::OnCallToDelegate(NetLogEventType type) {
   DCHECK(!calling_delegate_);
   DCHECK(blocked_by_.empty());
   calling_delegate_ = true;
-  net_log_.BeginEvent(NetLogEventType::URL_REQUEST_DELEGATE);
+  delegate_event_type_ = type;
+  net_log_.BeginEvent(type);
 }
 
 void URLRequest::OnCallToDelegateComplete() {
@@ -1166,7 +1168,8 @@ void URLRequest::OnCallToDelegateComplete() {
   if (!calling_delegate_)
     return;
   calling_delegate_ = false;
-  net_log_.EndEvent(NetLogEventType::URL_REQUEST_DELEGATE);
+  net_log_.EndEvent(delegate_event_type_);
+  delegate_event_type_ = NetLogEventType::FAILED;
 }
 
 #if BUILDFLAG(ENABLE_REPORTING)

net/url_request/url_request.h

@@ -34,6 +34,7 @@
 #include "net/http/http_request_headers.h"
 #include "net/http/http_response_headers.h"
 #include "net/http/http_response_info.h"
+#include "net/log/net_log_event_type.h"
 #include "net/log/net_log_with_source.h"
 #include "net/net_buildflags.h"
 #include "net/socket/connection_attempts.h"
@@ -812,8 +813,10 @@ class NET_EXPORT URLRequest : public base::SupportsUserData {
                     CookieOptions* options) const;
   bool CanEnablePrivacyMode() const;
 
-  // Called just before calling a delegate that may block a request.
-  void OnCallToDelegate();
+  // Called just before calling a delegate that may block a request. |type|
+  // should be the delegate's event type,
+  // e.g. NetLogEventType::NETWORK_DELEGATE_AUTH_REQUIRED.
+  void OnCallToDelegate(NetLogEventType type);
   // Called when the delegate lets a request continue.  Also called on
   // cancellation.
   void OnCallToDelegateComplete();
@@ -893,6 +896,10 @@ class NET_EXPORT URLRequest : public base::SupportsUserData {
   // A globally unique identifier for this request.
   const uint64_t identifier_;
 
+  // If |calling_delegate_| is true, the event type of the delegate being
+  // called.
+  NetLogEventType delegate_event_type_;
+
   // True if this request is currently calling a delegate, or is blocked waiting
   // for the URL request or network delegate to resume it.
   bool calling_delegate_;

net/url_request/url_request_http_job.cc

@@ -538,7 +538,8 @@ void URLRequestHttpJob::DestroyTransaction() {
 
 void URLRequestHttpJob::StartTransaction() {
   if (network_delegate()) {
-    OnCallToDelegate();
+    OnCallToDelegate(
+        NetLogEventType::NETWORK_DELEGATE_BEFORE_START_TRANSACTION);
     // The NetworkDelegate must watch for OnRequestDestroyed and not modify
     // |extra_headers| or invoke the callback after it's called. Not using a
     // WeakPtr here because it's not enough, the consumer has to watch for
@@ -990,7 +991,7 @@ void URLRequestHttpJob::OnStartCompleted(int result) {
       // Note that |this| may not be deleted until
       // |URLRequestHttpJob::OnHeadersReceivedCallback()| or
       // |NetworkDelegate::URLRequestDestroyed()| has been called.
-      OnCallToDelegate();
+      OnCallToDelegate(NetLogEventType::NETWORK_DELEGATE_HEADERS_RECEIVED);
       allowed_unsafe_redirect_url_ = GURL();
       // The NetworkDelegate must watch for OnRequestDestroyed and not modify
       // any of the arguments or invoke the callback after it's called. Not

net/url_request/url_request_job.cc

@@ -588,8 +588,8 @@ void URLRequestJob::NotifyRestartRequired() {
     request_->Restart();
 }
 
-void URLRequestJob::OnCallToDelegate() {
-  request_->OnCallToDelegate();
+void URLRequestJob::OnCallToDelegate(NetLogEventType type) {
+  request_->OnCallToDelegate(type);
 }
 
 void URLRequestJob::OnCallToDelegateComplete() {

net/url_request/url_request_job.h

@@ -283,7 +283,7 @@ class NET_EXPORT URLRequestJob : public base::PowerObserver {
   void NotifyRestartRequired();
 
   // See corresponding functions in url_request.h.
-  void OnCallToDelegate();
+  void OnCallToDelegate(NetLogEventType type);
   void OnCallToDelegateComplete();
 
   // Called to read raw (pre-filtered) data from this Job. Reads at most