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>
 
+#include "base/memory/ptr_util.h"
 #include "base/metrics/histogram_macros.h"
 #include "base/strings/string_number_conversions.h"
 #include "base/strings/string_util.h"
 #include "base/threading/thread_task_runner_handle.h"
 #include "base/values.h"
 #include "net/base/host_mapping_rules.h"
 #include "net/base/proxy_delegate.h"
 #include "net/http/bidirectional_stream_impl.h"
 #include "net/http/transport_security_state.h"
 #include "net/log/net_log_capture_mode.h"
 #include "net/log/net_log_event_type.h"
 #include "net/log/net_log_source.h"
 #include "net/log/net_log_with_source.h"
 #include "net/proxy/proxy_server.h"
 #include "net/spdy/spdy_session.h"
 #include "url/url_constants.h"
 
 namespace net {
 
 // 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);
 }
 
+std::unique_ptr<base::Value> NetLogJobControllerCallback(
+    const GURL* url,
+    bool is_preconnect,
+    NetLogCaptureMode /* capture_mode */) {
+  auto dict = base::MakeUnique<base::DictionaryValue>();
+  dict->SetString("url", url->possibly_invalid_spec());
+  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,
+    const HttpRequestInfo& request_info,
+    bool is_preconnect)
     : factory_(factory),
       session_(session),
       job_factory_(job_factory),
       request_(nullptr),
       delegate_(delegate),
-      is_preconnect_(false),
+      is_preconnect_(is_preconnect),
       alternative_job_net_error_(OK),
       job_bound_(false),
       main_job_is_blocked_(false),
       bound_job_(nullptr),
       can_start_alternative_proxy_job_(false),
       privacy_mode_(PRIVACY_MODE_DISABLED),
+      net_log_(
+          NetLogWithSource::Make(session->net_log(),
+                                 NetLogSourceType::HTTP_STREAM_JOB_CONTROLLER)),
       ptr_factory_(this) {
   DCHECK(factory);
+  net_log_.BeginEvent(NetLogEventType::HTTP_STREAM_JOB_CONTROLLER,
+                      base::Bind(&NetLogJobControllerCallback,
+                                 &request_info.url, 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,
+    const NetLogWithSource& source_net_log,
     HttpStreamRequest::StreamType stream_type,
     RequestPriority priority,
     const SSLConfig& server_ssl_config,
     const SSLConfig& proxy_ssl_config) {
   DCHECK(factory_);
   DCHECK(!request_);
 
   privacy_mode_ = request_info.privacy_mode;
 
   request_ = new Request(request_info.url, this, delegate,
-                         websocket_handshake_stream_create_helper, net_log,
-                         stream_type);
+                         websocket_handshake_stream_create_helper,
+                         source_net_log, stream_type);
+  // Associates |net_log_| with |source_net_log|.
+  source_net_log.AddEvent(NetLogEventType::HTTP_STREAM_JOB_CONTROLLER_BOUND,
+                          net_log_.source().ToEventParametersCallback());
+  net_log_.AddEvent(NetLogEventType::HTTP_STREAM_JOB_CONTROLLER_BOUND,
+                    source_net_log.source().ToEventParametersCallback());
 
   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_);
+  DCHECK(is_preconnect_);
 
   privacy_mode_ = request_info.privacy_mode;
 
-  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 318 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_net_error_ != OK)
       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 117 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;
 }
 
 bool HttpStreamFactoryImpl::JobController::HasPendingMainJob() const {
   return main_job_.get() != nullptr;
@@ skipping 17 matching lines @@
   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.
@@ skipping 428 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