[DO NOT SUBMIT, PATCH on commit 7fa349e632a44c152b05ca6a66ade5f2e5b3f139]

net/quic/chromium/quic_stream_factory.cc

Index: net/quic/chromium/quic_stream_factory.cc
diff --git a/net/quic/chromium/quic_stream_factory.cc b/net/quic/chromium/quic_stream_factory.cc
index 24ff534754f2831513eaacf8f54d5c5d1c7b21ac..30e719c7848ab83ca5c5a4ee7cfc27fcd18ecc8b 100644
--- a/net/quic/chromium/quic_stream_factory.cc
+++ b/net/quic/chromium/quic_stream_factory.cc
@@ -342,6 +342,8 @@ class QuicStreamFactory::Job {
 
   base::WeakPtr<Job> GetWeakPtr() { return weak_factory_.GetWeakPtr(); }
 
+  const NetLogWithSource net_log() { return job_net_log_; }
+
  private:
   enum IoState {
     STATE_NONE,
@@ -364,6 +366,7 @@ class QuicStreamFactory::Job {
   std::unique_ptr<QuicServerInfo> server_info_;
   bool started_another_job_;
   const NetLogWithSource net_log_;
+  const NetLogWithSource job_net_log_;
   int num_sent_client_hellos_;
   QuicChromiumClientSession* session_;
   CompletionCallback callback_;
@@ -391,9 +394,21 @@ QuicStreamFactory::Job::Job(QuicStreamFactory* factory,
       server_info_(std::move(server_info)),
       started_another_job_(false),
       net_log_(net_log),
+      job_net_log_(
+          NetLogWithSource::Make(net_log.net_log(),
+                                 NetLogSourceType::QUIC_STREAM_FACTORY_JOB)),
       num_sent_client_hellos_(0),
       session_(nullptr),
-      weak_factory_(this) {}
+      weak_factory_(this) {
+  job_net_log_.BeginEvent(
+      NetLogEventType::QUIC_STREAM_FACTORY_JOB,
+      NetLog::BoolCallback("resume_exisiting_session", false));
+  net_log_.AddEvent(NetLogEventType::QUIC_STREAM_FACTORY_JOB_BOUND,
+                    job_net_log_.source().ToEventParametersCallback());
+
+  job_net_log_.AddEvent(NetLogEventType::QUIC_STREAM_FACTORY_JOB_BOUND,
+                        net_log_.source().ToEventParametersCallback());
+}
 
 QuicStreamFactory::Job::Job(QuicStreamFactory* factory,
                             HostResolver* host_resolver,
@@ -407,11 +422,19 @@ QuicStreamFactory::Job::Job(QuicStreamFactory* factory,
       was_alternative_service_recently_broken_(false),  // unused
       started_another_job_(false),                      // unused
       net_log_(session->net_log()),                     // unused
+      job_net_log_(
+          NetLogWithSource::Make(session->net_log().net_log(),
+                                 NetLogSourceType::QUIC_STREAM_FACTORY_JOB)),
       num_sent_client_hellos_(0),
       session_(session),
-      weak_factory_(this) {}
+      weak_factory_(this) {
+  job_net_log_.BeginEvent(
+      NetLogEventType::QUIC_STREAM_FACTORY_JOB,
+      NetLog::BoolCallback("resume_exisiting_session", true));
+}
 
 QuicStreamFactory::Job::~Job() {
+  job_net_log_.EndEvent(NetLogEventType::QUIC_STREAM_FACTORY_JOB);
   // If disk cache has a pending WaitForDataReadyCallback, cancel that callback.
   if (server_info_)
     server_info_->ResetWaitForDataReadyCallback();
@@ -479,6 +502,7 @@ void QuicStreamFactory::Job::RunAuxilaryJob() {
 }
 
 void QuicStreamFactory::Job::Cancel() {
+  job_net_log_.AddEvent(NetLogEventType::QUIC_STREAM_FACTORY_JOB_CANCELLED);
   callback_.Reset();
   if (session_)
     session_->connection()->CloseConnection(
@@ -495,6 +519,9 @@ void QuicStreamFactory::Job::CancelWaitForDataReadyCallback() {
 }
 
 int QuicStreamFactory::Job::DoResolveHost() {
+  job_net_log_.BeginEvent(
+      NetLogEventType::QUIC_STREAM_FACTORY_JOB_RESOLVE_HOST,
+      NetLog::BoolCallback("load_server_info", server_info_.get() != nullptr));
   dns_resolution_start_time_ = base::TimeTicks::Now();
   // Start loading the data now, and wait for it after we resolve the host.
   if (server_info_)
@@ -505,10 +532,12 @@ int QuicStreamFactory::Job::DoResolveHost() {
       HostResolver::RequestInfo(key_.destination()), DEFAULT_PRIORITY,
       &address_list_,
       base::Bind(&QuicStreamFactory::Job::OnIOComplete, GetWeakPtr()),
-      &request_, net_log_);
+      &request_, job_net_log_);
 }
 
 int QuicStreamFactory::Job::DoResolveHostComplete(int rv) {
+  job_net_log_.EndEvent(NetLogEventType::QUIC_STREAM_FACTORY_JOB_RESOLVE_HOST);
+
   dns_resolution_end_time_ = base::TimeTicks::Now();
   if (rv != OK)
     return rv;
@@ -534,10 +563,12 @@ int QuicStreamFactory::Job::DoLoadServerInfo() {
 
   // To mitigate the effects of disk cache taking too long to load QUIC server
   // information, set up a timer to cancel WaitForDataReady's callback.
+
+  int64_t load_server_info_timeout_ms = 0;
   if (factory_->load_server_info_timeout_srtt_multiplier_ > 0) {
     const int kMaxLoadServerInfoTimeoutMs = 50;
     // Wait for DiskCache a maximum of 50ms.
-    int64_t load_server_info_timeout_ms =
+    load_server_info_timeout_ms =
         std::min(static_cast<int>(
                      (factory_->load_server_info_timeout_srtt_multiplier_ *
                       factory_->GetServerNetworkStatsSmoothedRttInMicroseconds(
@@ -553,14 +584,21 @@ int QuicStreamFactory::Job::DoLoadServerInfo() {
     }
   }
 
+  job_net_log_.BeginEvent(
+      NetLogEventType::QUIC_STREAM_FACTORY_JOB_LOAD_SERVER_INFO,
+      NetLog::Int64Callback("load_server_info_timeout_ms",
+                            load_server_info_timeout_ms));
+
   int rv = server_info_->WaitForDataReady(
       base::Bind(&QuicStreamFactory::Job::OnIOComplete, GetWeakPtr()));
   if (rv == ERR_IO_PENDING && factory_->enable_connection_racing()) {
     // If we are waiting to load server config from the disk cache, then start
     // another job.
     started_another_job_ = true;
+    job_net_log_.AddEvent(NetLogEventType::QUIC_STREAM_FACTORY_START_AUX_JOB);
     factory_->CreateAuxilaryJob(key_, cert_verify_flags_, net_log_);
   }
+
   return rv;
 }
 
@@ -568,6 +606,9 @@ int QuicStreamFactory::Job::DoLoadServerInfoComplete(int rv) {
   UMA_HISTOGRAM_TIMES("Net.QuicServerInfo.DiskCacheWaitForDataReadyTime",
                       base::TimeTicks::Now() - dns_resolution_end_time_);
 
+  job_net_log_.EndEvent(
+      NetLogEventType::QUIC_STREAM_FACTORY_JOB_LOAD_SERVER_INFO);
+
   if (rv != OK)
     server_info_.reset();
 
@@ -590,11 +631,14 @@ int QuicStreamFactory::Job::DoConnect() {
 
   bool require_confirmation = factory_->require_confirmation() ||
                               was_alternative_service_recently_broken_;
+  job_net_log_.BeginEvent(
+      NetLogEventType::QUIC_STREAM_FACTORY_JOB_CONNECT,
+      NetLog::BoolCallback("require_confirmation", require_confirmation));
 
   int rv = factory_->CreateSession(
       key_, cert_verify_flags_, std::move(server_info_), require_confirmation,
       address_list_, dns_resolution_start_time_, dns_resolution_end_time_,
-      net_log_, &session_);
+      job_net_log_, &session_);
   if (rv != OK) {
     DCHECK(rv != ERR_IO_PENDING);
     DCHECK(!session_);
@@ -620,6 +664,8 @@ int QuicStreamFactory::Job::DoConnect() {
 }
 
 int QuicStreamFactory::Job::DoResumeConnect() {
+  job_net_log_.BeginEvent(NetLogEventType::QUIC_STREAM_FACTORY_JOB_CONNECT,
+                          NetLog::BoolCallback("resume_connection", true));
   io_state_ = STATE_CONNECT_COMPLETE;
 
   int rv = session_->ResumeCryptoConnect(
@@ -629,6 +675,7 @@ int QuicStreamFactory::Job::DoResumeConnect() {
 }
 
 int QuicStreamFactory::Job::DoConnectComplete(int rv) {
+  job_net_log_.EndEvent(NetLogEventType::QUIC_STREAM_FACTORY_JOB_CONNECT);
   if (session_ && session_->error() == QUIC_CRYPTO_HANDSHAKE_STATELESS_REJECT) {
     num_sent_client_hellos_ += session_->GetNumSentClientHellos();
     if (num_sent_client_hellos_ >= QuicCryptoClientStream::kMaxClientHellos)
@@ -701,6 +748,7 @@ void QuicStreamRequest::SetSession(QuicChromiumClientSession* session) {
 }
 
 void QuicStreamRequest::OnRequestComplete(int rv) {
+  net_log_.EndEvent(NetLogEventType::QUIC_STREAM_FACTORY_CREATE_HTTP_STREAM);
   factory_ = nullptr;
   callback_.Run(rv);
 }
@@ -769,6 +817,9 @@ QuicStreamFactory::QuicStreamFactory(
     bool enable_token_binding)
     : require_confirmation_(true),
       net_log_(net_log),
+      quic_net_log_(
+          NetLogWithSource::Make(net_log,
+                                 NetLogSourceType::QUIC_STREAM_FACTORY)),
       host_resolver_(host_resolver),
       client_socket_factory_(client_socket_factory),
       http_server_properties_(http_server_properties),
@@ -970,6 +1021,9 @@ int QuicStreamFactory::Create(const QuicServerId& server_id,
                               base::StringPiece method,
                               const NetLogWithSource& net_log,
                               QuicStreamRequest* request) {
+  std::string server_id_string = server_id.ToString();
+  net_log.BeginEvent(NetLogEventType::QUIC_STREAM_FACTORY_CREATE_HTTP_STREAM,
+                     NetLog::StringCallback("server_id", &server_id_string));
   if (clock_skew_detector_.ClockSkewDetected(base::TimeTicks::Now(),
                                              base::Time::Now())) {
     while (!active_sessions_.empty()) {
@@ -989,6 +1043,8 @@ int QuicStreamFactory::Create(const QuicServerId& server_id,
     if (session->server_id().privacy_mode() == server_id.privacy_mode()) {
       request->SetSession(session);
       ++num_push_streams_created_;
+      net_log.EndEvent(NetLogEventType::QUIC_STREAM_FACTORY_CREATE_HTTP_STREAM,
+                       NetLog::BoolCallback("is_promised", true));
       return OK;
     }
     // This should happen extremely rarely (if ever), but if somehow a
@@ -1004,6 +1060,8 @@ int QuicStreamFactory::Create(const QuicServerId& server_id,
     if (it != active_sessions_.end()) {
       QuicChromiumClientSession* session = it->second;
       request->SetSession(session);
+      net_log.EndEvent(NetLogEventType::QUIC_STREAM_FACTORY_CREATE_HTTP_STREAM,
+                       NetLog::BoolCallback("active_session_exists", true));
       return OK;
     }
   }
@@ -1012,6 +1070,22 @@ int QuicStreamFactory::Create(const QuicServerId& server_id,
   if (HasActiveJob(server_id)) {
     active_requests_[request] = server_id;
     job_requests_map_[server_id].insert(request);
+    if (active_jobs_[server_id].size() == 1) {
+      const NetLogWithSource job_net_log =
+          active_jobs_[server_id].begin()->first->net_log();
+      job_net_log.AddEvent(NetLogEventType::QUIC_STREAM_FACTORY_JOB_BOUND,
+                           net_log.source().ToEventParametersCallback());
+      net_log.AddEvent(NetLogEventType::QUIC_STREAM_FACTORY_JOB_BOUND,
+                       job_net_log.source().ToEventParametersCallback());
+    }
+    // Safe access, HasActiveJob.
+    size_t job_count = active_jobs_[server_id].size();
+    net_log.AddEvent(
+        NetLogEventType::QUIC_STREAM_FACTORY_REQUEST_BOUND_TO_ACTIVE_JOB,
+        NetLog::Int64Callback("job_count", job_count));

[eroman, 2017/03/16 04:32:09]

nit: I don't think an int64 is necessary here.

+    net_log.AddEvent(
+        NetLogEventType::QUIC_STREAM_FACTORY_REQUEST_BOUND_TO_ACTIVE_JOB,
+        NetLog::BoolCallback("active_jobs_exist", true));
     return ERR_IO_PENDING;
   }
 
@@ -1022,6 +1096,9 @@ int QuicStreamFactory::Create(const QuicServerId& server_id,
       if (destination.Equals(all_sessions_[session].destination()) &&
           session->CanPool(server_id.host(), server_id.privacy_mode())) {
         request->SetSession(session);
+        net_log.EndEvent(
+            NetLogEventType::QUIC_STREAM_FACTORY_CREATE_HTTP_STREAM,
+            NetLog::BoolCallback("pool_to_active_session", true));
         return OK;
       }
     }
@@ -1048,6 +1125,11 @@ int QuicStreamFactory::Create(const QuicServerId& server_id,
   ignore_result(StartCertVerifyJob(server_id, cert_verify_flags, net_log));
 
   QuicSessionKey key(destination, server_id);
+
+  size_t job_count;
+  // Log that we create a new Job to serve the request.
+  net_log.AddEvent(NetLogEventType::QUIC_STREAM_FACTORY_REQUEST_CREATE_NEW_JOB);
+
   std::unique_ptr<Job> job = base::MakeUnique<Job>(
       this, host_resolver_, key, WasQuicRecentlyBroken(server_id),
       cert_verify_flags, std::move(quic_server_info), net_log);
@@ -1058,9 +1140,34 @@ int QuicStreamFactory::Create(const QuicServerId& server_id,
     job_requests_map_[server_id].insert(request);
     Job* job_ptr = job.get();
     active_jobs_[server_id][job_ptr] = std::move(job);
+
+    // Safe access after insertion.
+    job_count = active_jobs_[server_id].size();
+
+    // The new job can't finish immediately, added to active job list.
+    net_log.AddEvent(
+        NetLogEventType::QUIC_STREAM_FACTORY_REQUEST_NEW_JOB_PENDING,
+        NetLog::Int64Callback("active_job_count", job_count));

[eroman, 2017/03/16 04:32:08]

same

+
+    // Once one of the associated job finishes, QuicStreamFactory::OnJobComplete
+    // will be invoked. On success, notify all the requests. Else if there's no
+    // other job, it will notify request(s). Else, ignore if there's other jobs
+    // running.
     return rv;
   }
   if (rv == OK) {
+    job_count = 0;
+    if (HasActiveJob(server_id)) {
+      job_count = active_jobs_[server_id].size();
+    }
+    bool active_session_found =
+        (active_sessions_.find(server_id) != active_sessions_.end());
+    net_log.AddEvent(
+        NetLogEventType::QUIC_STREAM_FACTORY_REQUEST_NEW_JOB_SUCCEED,
+        NetLog::Int64Callback("job_count", job_count));
+    net_log.AddEvent(
+        NetLogEventType::QUIC_STREAM_FACTORY_REQUEST_NEW_JOB_SUCCEED,
+        NetLog::BoolCallback("active_session_found", active_session_found));
     // TODO(rtenneti): crbug.com/498823 - revert active_sessions_.empty()
     // related changes.
     if (active_sessions_.empty())
@@ -1071,7 +1178,22 @@ int QuicStreamFactory::Create(const QuicServerId& server_id,
       return ERR_QUIC_PROTOCOL_ERROR;
     QuicChromiumClientSession* session = it->second;
     request->SetSession(session);
+  } else {
+    job_count = 0;
+    if (HasActiveJob(server_id)) {
+      job_count = active_jobs_[server_id].size();
+    }
+
+    bool active_session_found =
+        (active_sessions_.find(server_id) != active_sessions_.end());
+    net_log.AddEvent(
+        NetLogEventType::QUIC_STREAM_FACTORY_REQUEST_NEW_JOB_FAILED,
+        NetLog::Int64Callback("job_count", job_count));
+    net_log.AddEvent(
+        NetLogEventType::QUIC_STREAM_FACTORY_REQUEST_NEW_JOB_FAILED,
+        NetLog::BoolCallback("active_session_found", active_session_found));
   }
+  net_log.EndEvent(NetLogEventType::QUIC_STREAM_FACTORY_CREATE_HTTP_STREAM);
   return rv;
 }
 
@@ -1135,17 +1257,39 @@ void QuicStreamFactory::OnJobComplete(Job* job, int rv) {
   // Copy |server_id|, because |job| might be destroyed before this method
   // returns.
   const QuicServerId server_id(job->key().server_id());
+  std::string server_id_string = server_id.ToString();
+  quic_net_log_.BeginEvent(
+      NetLogEventType::QUIC_STREAM_FACTORY_JOB_COMPLETE,
+      NetLog::StringCallback("server id", &server_id_string));
+
   if (rv != OK) {
+    CHECK(HasActiveJob(server_id));
     JobSet* jobs = &(active_jobs_[server_id]);
     if (jobs->size() > 1) {
       // If there is another pending job, then we can delete this job and let
       // the other job handle the request.
+      job->net_log().AddEvent(
+          NetLogEventType::QUIC_STREAM_FACTORY_JOB_CANCELLED_BY_FACTORY);
+
       job->Cancel();
+
+      size_t job_count = active_jobs_[server_id].size();
+      quic_net_log_.AddEvent(
+          NetLogEventType::QUIC_STREAM_FACTORY_REQUEST_ACTIVE_JOB_COUNT,
+          NetLog::Int64Callback("job count before erase", job_count));
       jobs->erase(job);
+      job_count = active_jobs_[server_id].size();
+      quic_net_log_.EndEvent(
+          NetLogEventType::QUIC_STREAM_FACTORY_JOB_COMPLETE,
+          NetLog::BoolCallback("has_active_job", HasActiveJob(server_id)));
       return;
     }
   }
 
+  job->net_log().AddEvent(
+      NetLogEventType::QUIC_STREAM_FACTORY_JOB_COMPLTE_FROM_FACTORY,
+      NetLog::BoolCallback("is_success", rv == OK));
+
   if (rv == OK) {
     if (!always_require_handshake_confirmation_)
       set_require_confirmation(false);
@@ -1173,14 +1317,28 @@ void QuicStreamFactory::OnJobComplete(Job* job, int rv) {
     request->OnRequestComplete(rv);
   }
 
+  CHECK(HasActiveJob(server_id));
+
   for (auto& other_job : active_jobs_[server_id]) {
-    if (other_job.first != job)
+    if (other_job.first != job) {
+      other_job.first->net_log().AddEvent(
+          NetLogEventType::QUIC_STREAM_FACTORY_JOB_CANCELLED_BY_FACTORY);
       other_job.first->Cancel();
+    }
   }
 
+  size_t job_count = active_jobs_[server_id].size();
+  quic_net_log_.AddEvent(
+      NetLogEventType::QUIC_STREAM_FACTORY_REQUEST_ACTIVE_JOB_COUNT,
+      NetLog::Int64Callback("job count before clear", job_count));
+
   active_jobs_[server_id].clear();
   active_jobs_.erase(server_id);
   job_requests_map_.erase(server_id);
+
+  quic_net_log_.EndEvent(
+      NetLogEventType::QUIC_STREAM_FACTORY_JOB_COMPLETE,
+      NetLog::BoolCallback("has_active_job", HasActiveJob(server_id)));
 }
 
 void QuicStreamFactory::OnCertVerifyJobComplete(CertVerifierJob* job, int rv) {
@@ -1578,8 +1736,18 @@ bool QuicStreamFactory::HasActiveSession(const QuicServerId& server_id) const {
   return base::ContainsKey(active_sessions_, server_id);
 }
 
-bool QuicStreamFactory::HasActiveJob(const QuicServerId& server_id) const {
-  return base::ContainsKey(active_jobs_, server_id);
+bool QuicStreamFactory::HasActiveJob(const QuicServerId& server_id) {
+  bool has = base::ContainsKey(active_jobs_, server_id);
+
+  size_t job_count = 0;
+  if (has) {
+    job_count = active_jobs_[server_id].size();
+  }
+
+  quic_net_log_.AddEvent(
+      NetLogEventType::QUIC_STREAM_FACTORY_REQUEST_ACTIVE_JOB_COUNT,
+      NetLog::Int64Callback("has_active_job_count", job_count));
+  return has;
 }
 
 bool QuicStreamFactory::HasActiveCertVerifierJob(