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)
     : 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(net_log.net_log(),
+                                 NetLogSourceType::HTTP_STREAM_JOB_CONTROLLER)),
       ptr_factory_(this) {
   DCHECK(factory);
+  net_log.AddEvent(NetLogEventType::HTTP_STREAM_JOB_CONTROLLER,
+                   net_log_.source().ToEventParametersCallback());
+  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);
 
   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_);
 
-  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 323 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_;
 }
 
 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 367 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