Improve HttpStreamFactory NetLog events

net/http/http_stream_factory_impl_job_controller.cc

Index: net/http/http_stream_factory_impl_job_controller.cc
diff --git a/net/http/http_stream_factory_impl_job_controller.cc b/net/http/http_stream_factory_impl_job_controller.cc
index 052a17e3da2ab5a6d5a396109eb900c3d88ba903..f7396a1bf83101bed9846941035265edf95586a2 100644
--- a/net/http/http_stream_factory_impl_job_controller.cc
+++ b/net/http/http_stream_factory_impl_job_controller.cc
@@ -36,30 +36,55 @@ std::unique_ptr<base::Value> NetLogHttpStreamJobDelayCallback(
   return std::move(dict);
 }
 
+// Returns parameters associated with the start of a JobController.
+std::unique_ptr<base::Value> NetLogJobControllerCallback(
+    const NetLogSource& source,
+    bool is_preconnect,
+    NetLogCaptureMode /* capture_mode */) {
+  std::unique_ptr<base::DictionaryValue> dict(new base::DictionaryValue());
+  if (source.IsValid())
+    source.AddToEventParameters(dict.get());
+  dict->SetBoolean("is_preconnect", is_preconnect);
+  return std::move(dict);
+}
+
 HttpStreamFactoryImpl::JobController::JobController(
     HttpStreamFactoryImpl* factory,
     HttpStreamRequest::Delegate* delegate,
     HttpNetworkSession* session,
-    JobFactory* job_factory)
+    JobFactory* job_factory,
+    bool is_preconnect,
+    const NetLogWithSource& net_log)

[mmenke, 2017/01/25 19:32:17]

Calling this net_log and having it be different from net_log_ is very confusing.
 source_net_log?

[eroman, 2017/01/25 19:55:27]

Strongly agreed -- I found this quite confusing when reading. There are a
variety of checks around "is valid" in this file, and similarly passing a
"dummy" netlog in HttpStreamFactoryImpl.

I think this can be solved by removing the parameter from the constructor
alltogether, and making the association be a separate method. For instance in
HttpStreamFactoryImpl you might call some new method AssociateWithNetLogSource()
in the non-preconnect case:


HttpStreamFactoryImpl::RequestStreamInternal(...) {
  auto job_controller = base::MakeUnique<JobController>(XXX);

  // Call an extra function to associate the two net log Sources
  job_controller->AssociateWithNetSource(net_log.source());
  ...
}

HttpStreamFactoryImpl::PreconnectStreams(...) {
  // Note, no use of "dummy_net_log_with_source" anywhere
  auto job_controller = base::MakeUnique<JobController>(XXX);
  ...
}


HttpStreamFactoryImpl::JobController::AssociateWithNetLogSource(source) {
< Emit two separate "bound" events. One that associates source with
net_log_.source(), and another for the opposite direction. This does mean
introducing a separate net log event type rather than overloading the possible
parameters for HTTP_STREAM_JOB_CONTROLLER>
}

[xunjieli, 2017/01/25 21:41:49]

Done.

[xunjieli, 2017/01/25 21:41:49]

Done. Great idea. That's neat!

     : factory_(factory),
       session_(session),
       job_factory_(job_factory),
       request_(nullptr),
       delegate_(delegate),
-      is_preconnect_(false),
+      is_preconnect_(is_preconnect),
       alternative_job_failed_(false),
       job_bound_(false),
       main_job_is_blocked_(false),
       bound_job_(nullptr),
       can_start_alternative_proxy_job_(false),
+      net_log_(
+          NetLogWithSource::Make(session->net_log(),
+                                 NetLogSourceType::HTTP_STREAM_JOB_CONTROLLER)),
       ptr_factory_(this) {
   DCHECK(factory);
+  if (net_log.source().IsValid()) {

[mmenke, 2017/01/25 19:32:17]

Not needed - AddEvent checks if the NetLogWithSource has an nullptr for the
NetLog and if so, does nothing.  And if the NetLog is non-NULL, then the source
must be valid.

Or do mean to check net_log_ instead of net_log?  If so, should probably check
net_log_.net_log().

[xunjieli, 2017/01/25 21:41:49]

Done. Thanks! I didn't realized that AddEvent() checks if the NetLogWithSource
has a non-null NetLog.

+    net_log.AddEvent(NetLogEventType::HTTP_STREAM_JOB_CONTROLLER,
+                     net_log_.source().ToEventParametersCallback());

[Zhongyi Shi, 2017/01/20 22:42:10]

I am unfamiliar with NetLog, why do we need |net_log| to be passed in? Is that
for building dependency?

[xunjieli, 2017/01/23 14:24:24]

Yes, this is for linking the caller of JobController (in this case it's the
URLRequest) with the JobController event.

Here's an example netlog
https://drive.google.com/a/google.com/file/d/0B_9WseIqRoaFTEZSLUw4aFUyc2M/vie...

+  }
+  net_log_.BeginEvent(NetLogEventType::HTTP_STREAM_JOB_CONTROLLER,
+                      base::Bind(&NetLogJobControllerCallback, net_log.source(),
+                                 is_preconnect));
 }
 
 HttpStreamFactoryImpl::JobController::~JobController() {
   main_job_.reset();
   alternative_job_.reset();
   bound_job_ = nullptr;
+  net_log_.EndEvent(NetLogEventType::HTTP_STREAM_JOB_CONTROLLER);
 }
 
 bool HttpStreamFactoryImpl::JobController::for_websockets() {
@@ -71,7 +96,6 @@ HttpStreamFactoryImpl::Request* HttpStreamFactoryImpl::JobController::Start(
     HttpStreamRequest::Delegate* delegate,
     WebSocketHandshakeStreamBase::CreateHelper*
         websocket_handshake_stream_create_helper,
-    const NetLogWithSource& net_log,
     HttpStreamRequest::StreamType stream_type,
     RequestPriority priority,
     const SSLConfig& server_ssl_config,
@@ -80,11 +104,11 @@ HttpStreamFactoryImpl::Request* HttpStreamFactoryImpl::JobController::Start(
   DCHECK(!request_);
 
   request_ = new Request(request_info.url, this, delegate,
-                         websocket_handshake_stream_create_helper, net_log,
+                         websocket_handshake_stream_create_helper, &net_log_,
                          stream_type);

[mmenke, 2017/01/25 19:32:17]

Should the request really be using the Controller's log?  It seems like the
request is scoped to the HttpNetworkTransaction, and it uses the controller, so
it should look like:

<URL_REQUEST's events>
+STREAM_REQUEST
     source_dependency: <link to controller>
  BOUND_TO_JOB
     source_dependency: <link to job (Shortcut, to avoid having to look at
controller, similar to the event in the controller)>
-STREAM_REQUEST

[xunjieli, 2017/01/25 21:41:49]

Done.

 
   CreateJobs(request_info, priority, server_ssl_config, proxy_ssl_config,
-             delegate, stream_type, net_log);
+             delegate, stream_type);
 
   return request_;
 }
@@ -97,7 +121,6 @@ void HttpStreamFactoryImpl::JobController::Preconnect(
   DCHECK(!main_job_);
   DCHECK(!alternative_job_);

[mmenke, 2017/01/25 19:32:17]

DCHECK(is_preconnect_);?

[eroman, 2017/01/25 19:55:27]

+1, I had same comment.

[xunjieli, 2017/01/25 21:41:49]

Done.

 
-  is_preconnect_ = true;
   HostPortPair destination(HostPortPair::FromURL(request_info.url));
   GURL origin_url = ApplyHostMappingRules(request_info.url, &destination);
 
@@ -434,7 +457,6 @@ void HttpStreamFactoryImpl::JobController::OnNewSpdySessionReady(
   const bool was_alpn_negotiated = job->was_alpn_negotiated();
   const NextProto negotiated_protocol = job->negotiated_protocol();
   const bool using_spdy = job->using_spdy();
-  const NetLogWithSource net_log = job->net_log();
 
   // Cache this so we can still use it if the JobController is deleted.
   HttpStreamFactoryImpl* factory = factory_;
@@ -478,7 +500,7 @@ void HttpStreamFactoryImpl::JobController::OnNewSpdySessionReady(
   if (spdy_session && spdy_session->IsAvailable()) {
     factory->OnNewSpdySessionReady(spdy_session, direct, used_ssl_config,
                                    used_proxy_info, was_alpn_negotiated,
-                                   negotiated_protocol, using_spdy, net_log);
+                                   negotiated_protocol, using_spdy);
   }
   if (is_job_orphaned) {
     OnOrphanedJobComplete(job);
@@ -516,7 +538,7 @@ void HttpStreamFactoryImpl::JobController::AddConnectionAttemptsToRequest(
 }
 
 void HttpStreamFactoryImpl::JobController::ResumeMainJob() {
-  main_job_->net_log().AddEvent(
+  net_log_.AddEvent(
       NetLogEventType::HTTP_STREAM_JOB_DELAYED,
       base::Bind(&NetLogHttpStreamJobDelayCallback, main_job_wait_time_));
 
@@ -616,10 +638,7 @@ void HttpStreamFactoryImpl::JobController::
 
 const NetLogWithSource* HttpStreamFactoryImpl::JobController::GetNetLog(
     Job* job) const {
-  if (is_preconnect_ || (job_bound_ && bound_job_ != job))
-    return nullptr;
-  DCHECK(request_);
-  return &request_->net_log();
+  return &net_log_;

[eroman, 2017/01/25 19:55:27]

does this still need to check for |bound_job_ != job| ?

[xunjieli, 2017/01/25 21:41:48]

No. The check is not necessary. Before the change, net_log is null when request_
is gone. In the new change, JobController has a always valid net_log_ to make
preconnect & orphaned job events show up.

 }
 
 void HttpStreamFactoryImpl::JobController::MaybeSetWaitTimeForMainJob(
@@ -640,8 +659,7 @@ void HttpStreamFactoryImpl::JobController::CreateJobs(
     const SSLConfig& server_ssl_config,
     const SSLConfig& proxy_ssl_config,
     HttpStreamRequest::Delegate* delegate,
-    HttpStreamRequest::StreamType stream_type,
-    const NetLogWithSource& net_log) {
+    HttpStreamRequest::StreamType stream_type) {
   DCHECK(!main_job_);
   DCHECK(!alternative_job_);
   HostPortPair destination(HostPortPair::FromURL(request_info.url));
@@ -649,7 +667,7 @@ void HttpStreamFactoryImpl::JobController::CreateJobs(
 
   main_job_.reset(job_factory_->CreateJob(
       this, MAIN, session_, request_info, priority, server_ssl_config,
-      proxy_ssl_config, destination, origin_url, net_log.net_log()));
+      proxy_ssl_config, destination, origin_url, net_log_.net_log()));
   AttachJob(main_job_.get());
 
   // Create an alternative job if alternative service is set up for this domain.
@@ -670,7 +688,7 @@ void HttpStreamFactoryImpl::JobController::CreateJobs(
     alternative_job_.reset(job_factory_->CreateJob(
         this, ALTERNATIVE, session_, request_info, priority, server_ssl_config,
         proxy_ssl_config, alternative_destination, origin_url,
-        alternative_service, net_log.net_log()));
+        alternative_service, net_log_.net_log()));
     AttachJob(alternative_job_.get());
 
     main_job_is_blocked_ = true;
@@ -700,13 +718,8 @@ void HttpStreamFactoryImpl::JobController::BindJob(Job* job) {
   bound_job_ = job;
   factory_->request_map_.erase(job);
 
-  request_->net_log().AddEvent(
-      NetLogEventType::HTTP_STREAM_REQUEST_BOUND_TO_JOB,
-      job->net_log().source().ToEventParametersCallback());
-  job->net_log().AddEvent(
-      NetLogEventType::HTTP_STREAM_JOB_BOUND_TO_REQUEST,
-      request_->net_log().source().ToEventParametersCallback());
-
+  net_log_.AddEvent(NetLogEventType::HTTP_STREAM_REQUEST_BOUND_TO_JOB,
+                    job->net_log().source().ToEventParametersCallback());
   OrphanUnboundJob();
 }