Improve HttpStreamFactory NetLog events

net/http/http_stream_factory_impl_job_controller.cc

 // Copyright (c) 2016 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "net/http/http_stream_factory_impl_job_controller.h"
 
 #include <memory>
 #include <string>
 #include <utility>
 
@@ skipping 18 matching lines @@
 
 // Returns parameters associated with the delay of the HTTP stream job.
 std::unique_ptr<base::Value> NetLogHttpStreamJobDelayCallback(
     base::TimeDelta delay,
     NetLogCaptureMode /* capture_mode */) {
   std::unique_ptr<base::DictionaryValue> dict(new base::DictionaryValue());
   dict->SetInteger("resume_after_ms", static_cast<int>(delay.InMilliseconds()));
   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() {
   return factory_->for_websockets_;
 }
 
 HttpStreamFactoryImpl::Request* HttpStreamFactoryImpl::JobController::Start(
     const HttpRequestInfo& request_info,
     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,
     const SSLConfig& proxy_ssl_config) {
   DCHECK(factory_);
   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_;
 }
 
 void HttpStreamFactoryImpl::JobController::Preconnect(
     int num_streams,
     const HttpRequestInfo& request_info,
     const SSLConfig& server_ssl_config,
     const SSLConfig& proxy_ssl_config) {
   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);
 
   const AlternativeService alternative_service = GetAlternativeServiceFor(
       request_info, nullptr, HttpStreamRequest::HTTP_STREAM);
 
   if (alternative_service.protocol != kProtoUnknown) {
     if (session_->params().quic_disable_preconnect_if_0rtt &&
         alternative_service.protocol == kProtoQUIC &&
         session_->quic_stream_factory()->ZeroRTTEnabledFor(QuicServerId(
@@ skipping 316 matching lines @@
   DCHECK(!is_preconnect_);
 
   bool is_job_orphaned = IsJobOrphaned(job);
 
   // Cache these values in case the job gets deleted.
   const SSLConfig used_ssl_config = job->server_ssl_config();
   const ProxyInfo used_proxy_info = job->proxy_info();
   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_;
 
   // Notify |request_|.
   if (!is_preconnect_ && !is_job_orphaned) {
     if (job->job_type() == MAIN && alternative_job_failed_)
       ReportBrokenAlternativeService();
 
     DCHECK(request_);
@@ skipping 23 matching lines @@
       DCHECK(stream);
       delegate_->OnStreamReady(used_ssl_config, used_proxy_info,
                                stream.release());
     }
   }
 
   // Notify |factory_|. |request_| and |bounded_job_| might be deleted already.
   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);
   }
 }
 
 void HttpStreamFactoryImpl::JobController::OnPreconnectsComplete(Job* job) {
   DCHECK_EQ(main_job_.get(), job);
   main_job_.reset();
   factory_->OnPreconnectsCompleteInternal();
@@ skipping 17 matching lines @@
     Job* job,
     const ConnectionAttempts& attempts) {
   if (is_preconnect_ || (job_bound_ && bound_job_ != job))
     return;
 
   DCHECK(request_);
   request_->AddConnectionAttempts(attempts);
 }
 
 void HttpStreamFactoryImpl::JobController::ResumeMainJob() {
-  main_job_->net_log().AddEvent(
+  net_log_.AddEvent(
       NetLogEventType::HTTP_STREAM_JOB_DELAYED,
       base::Bind(&NetLogHttpStreamJobDelayCallback, main_job_wait_time_));
 
   main_job_->Resume();
   main_job_wait_time_ = base::TimeDelta();
 }
 
 void HttpStreamFactoryImpl::JobController::MaybeResumeMainJob(
     Job* job,
     const base::TimeDelta& delay) {
@@ skipping 79 matching lines @@
     DCHECK(base::ContainsKey(request_set, request_));
     request_set.erase(request_);
     if (request_set.empty())
       spdy_session_request_map.erase(*spdy_session_key);
     request_->ResetSpdySessionKey();
   }
 }
 
 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(
     const base::TimeDelta& delay) {
   if (main_job_is_blocked_)
     main_job_wait_time_ = delay;
 }
 
 WebSocketHandshakeStreamBase::CreateHelper* HttpStreamFactoryImpl::
     JobController::websocket_handshake_stream_create_helper() {
   DCHECK(request_);
   return request_->websocket_handshake_stream_create_helper();
 }
 
 void HttpStreamFactoryImpl::JobController::CreateJobs(
     const HttpRequestInfo& request_info,
     RequestPriority priority,
     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));
   GURL origin_url = ApplyHostMappingRules(request_info.url, &destination);
 
   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.
   const AlternativeService alternative_service =
       GetAlternativeServiceFor(request_info, delegate, stream_type);
 
   if (alternative_service.protocol != kProtoUnknown) {
     // Never share connection with other jobs for FTP requests.
     DVLOG(1) << "Selected alternative service (host: "
              << alternative_service.host_port_pair().host()
              << " port: " << alternative_service.host_port_pair().port() << ")";
 
     DCHECK(!request_info.url.SchemeIs(url::kFtpScheme));
     HostPortPair alternative_destination(alternative_service.host_port_pair());
     ignore_result(
         ApplyHostMappingRules(request_info.url, &alternative_destination));
 
     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;
     alternative_job_->Start(request_->stream_type());
   } else {
     can_start_alternative_proxy_job_ = true;
   }
   // Even if |alternative_job| has already finished, it will not have notified
   // the request yet, since we defer that to the next iteration of the
   // MessageLoop, so starting |main_job_| is always safe.
   main_job_->Start(request_->stream_type());
 }
 
 void HttpStreamFactoryImpl::JobController::AttachJob(Job* job) {
   DCHECK(job);
   factory_->request_map_[job] = request_;
 }
 
 void HttpStreamFactoryImpl::JobController::BindJob(Job* job) {
   DCHECK(request_);
   DCHECK(job);
   DCHECK(job == alternative_job_.get() || job == main_job_.get());
   DCHECK(!job_bound_);
   DCHECK(!bound_job_);
 
   job_bound_ = true;
   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();
 }
 
 void HttpStreamFactoryImpl::JobController::CancelJobs() {
   DCHECK(request_);
   RemoveRequestFromSpdySessionRequestMap();
   if (job_bound_)
     return;
   if (alternative_job_) {
     factory_->request_map_.erase(alternative_job_.get());
@@ skipping 377 matching lines @@
     return;
   DCHECK(alternative_job_->alternative_proxy_server().is_valid());
   alternative_job_->Start(request_->stream_type());
 }
 
 bool HttpStreamFactoryImpl::JobController::IsJobOrphaned(Job* job) const {
   return !request_ || (job_bound_ && bound_job_ != job);
 }
 
 }  // namespace net