[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..69301b05f1c219b1628b8376fa1f47b8e4db8622 100644
--- a/net/quic/chromium/quic_stream_factory.cc
+++ b/net/quic/chromium/quic_stream_factory.cc
@@ -120,6 +120,26 @@ std::unique_ptr<base::Value> NetLogQuicConnectionMigrationSuccessCallback(
   return std::move(dict);
 }
 
+std::unique_ptr<base::Value> NetLogQuicSessionCurrentStatusCallback(
+    QuicServerId server_id,
+    bool received_go_away,
+    bool received_read_error,
+    bool connection_closed,
+    bool notified_session_going_away,
+    bool notified_session_closed_later,
+    bool notified_session_closed,
+    NetLogCaptureMode capture_mode) {
+  std::unique_ptr<base::DictionaryValue> dict(new base::DictionaryValue());
+  dict->SetString("server_id", server_id.ToString());
+  dict->SetBoolean("received_go_away", received_go_away);
+  dict->SetBoolean("received_read_error", received_read_error);
+  dict->SetBoolean("connection_closed", connection_closed);
+  dict->SetBoolean("notified_session_going_away", notified_session_going_away);
+  dict->SetBoolean("notified_session_closed_later", notified_session_closed_later);
+  dict->SetBoolean("notified_session_closed", notified_session_closed);
+  return std::move(dict);
+}
+
 // Helper class that is used to log a connection migration event.
 class ScopedConnectionMigrationEventLog {
  public:
@@ -342,6 +362,11 @@ class QuicStreamFactory::Job {
 
   base::WeakPtr<Job> GetWeakPtr() { return weak_factory_.GetWeakPtr(); }
 
+  const NetLogWithSource net_log() { return job_net_log_; }
+
+  // Log this Job's current state into NetLog.
+  void LogCurrentStatus();
+
  private:
   enum IoState {
     STATE_NONE,
@@ -353,6 +378,10 @@ class QuicStreamFactory::Job {
     STATE_RESUME_CONNECT,
     STATE_CONNECT_COMPLETE,
   };
+
+  bool session_was_active_;
+  bool crypto_connect_io_pending_;
+
   IoState io_state_;
 
   QuicStreamFactory* factory_;
@@ -364,6 +393,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_;
@@ -381,7 +411,9 @@ QuicStreamFactory::Job::Job(QuicStreamFactory* factory,
                             int cert_verify_flags,
                             std::unique_ptr<QuicServerInfo> server_info,
                             const NetLogWithSource& net_log)
-    : io_state_(STATE_RESOLVE_HOST),
+    : session_was_active_(false),
+      crypto_connect_io_pending_(false),
+      io_state_(STATE_RESOLVE_HOST),
       factory_(factory),
       host_resolver_(host_resolver),
       key_(key),
@@ -391,15 +423,29 @@ 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,
                             QuicChromiumClientSession* session,
                             const QuicSessionKey& key)
-    : io_state_(STATE_RESUME_CONNECT),
+    : session_was_active_(false),
+      crypto_connect_io_pending_(false),
+      io_state_(STATE_RESUME_CONNECT),
       factory_(factory),
       host_resolver_(host_resolver),  // unused
       key_(key),
@@ -407,11 +453,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();
@@ -425,6 +479,68 @@ int QuicStreamFactory::Job::Run(const CompletionCallback& callback) {
   return rv > 0 ? OK : rv;
 }
 
+void QuicStreamFactory::Job::LogCurrentStatus() {
+  switch (io_state_) {
+    case STATE_RESOLVE_HOST:
+      job_net_log_.AddEvent(NetLogEventType::QUIC_STREAM_FACTORY_JOB_RESOLVE_HOST,
+                            NetLog::BoolCallback("is_next", true));
+      break;
+    case STATE_RESOLVE_HOST_COMPLETE:
+      job_net_log_.AddEvent(NetLogEventType::QUIC_STREAM_FACTORY_JOB_RESOLVE_HOST,
+                            NetLog::BoolCallback("is_current", true));
+      break;
+    case STATE_LOAD_SERVER_INFO:
+      job_net_log_.AddEvent(NetLogEventType::QUIC_STREAM_FACTORY_JOB_LOAD_SERVER_INFO,
+                            NetLog::BoolCallback("is_next", true));
+      break;
+    case STATE_LOAD_SERVER_INFO_COMPLETE:
+      job_net_log_.AddEvent(NetLogEventType::QUIC_STREAM_FACTORY_JOB_LOAD_SERVER_INFO,
+                            NetLog::BoolCallback("is_current", true));
+      break;
+    case STATE_CONNECT:
+      job_net_log_.AddEvent(NetLogEventType::QUIC_STREAM_FACTORY_JOB_CONNECT,
+                            NetLog::BoolCallback("is_next_normal", true));
+      break;
+    case STATE_RESUME_CONNECT:
+      job_net_log_.AddEvent(NetLogEventType::QUIC_STREAM_FACTORY_JOB_CONNECT,
+                            NetLog::BoolCallback("is_next_resume", true));
+      break;
+    case STATE_CONNECT_COMPLETE:
+      job_net_log_.AddEvent(NetLogEventType::QUIC_STREAM_FACTORY_JOB_CONNECT,
+                            NetLog::BoolCallback("is_current", true));
+      break;
+    case STATE_NONE:
+      job_net_log_.AddEvent(NetLogEventType::QUIC_STREAM_FACTORY_JOB_CONNECT,
+                            NetLog::BoolCallback("is_current", true));
+      break;
+    default:
+      break;
+  }
+  job_net_log_.AddEvent(NetLogEventType::QUIC_STREAM_FACTORY_JOB_LOG,
+                        NetLog::BoolCallback("was_session_active", session_was_active_));
+  job_net_log_.AddEvent(NetLogEventType::QUIC_STREAM_FACTORY_JOB_LOG,
+                        NetLog::BoolCallback("session_not_null", session_ != nullptr));
+  // Log the crypto status IF ANY.
+  job_net_log_.AddEvent(NetLogEventType::QUIC_STREAM_FACTORY_JOB_LOG,
+                        NetLog::BoolCallback("crypto_connect_io_pending",
+                                             crypto_connect_io_pending_));
+  if (session_) {
+    job_net_log_.AddEvent(NetLogEventType::QUIC_STREAM_FACTORY_JOB_LOG,
+                          NetLog::BoolCallback("session_callback_not_run",
+                                               session_->callback_not_null()));
+    job_net_log_.AddEvent(NetLogEventType::QUIC_STREAM_FACTORY_JOB_LOG,
+                          base::Bind(&NetLogQuicSessionCurrentStatusCallback,
+                                     session_->server_id(),
+                                     session_->received_go_away_,
+                                     session_->received_read_error_,
+                                     session_->connection_closed_,
+                                     session_->notified_session_going_away_,
+                                     session_->notified_session_closed_later_,
+                                     session_->notified_session_closed_));
+  }
+}
+
+
 int QuicStreamFactory::Job::DoLoop(int rv) {
   TRACE_EVENT0(kNetTracingCategory, "QuicStreamFactory::Job::DoLoop");
   do {
@@ -479,6 +595,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 +612,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 +625,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;
@@ -517,8 +639,10 @@ int QuicStreamFactory::Job::DoResolveHostComplete(int rv) {
 
   // Inform the factory of this resolution, which will set up
   // a session alias, if possible.
-  if (factory_->OnResolution(key_, address_list_))
+  if (factory_->OnResolution(key_, address_list_)) {
+    session_was_active_ = true;
     return OK;
+  }
 
   if (server_info_)
     io_state_ = STATE_LOAD_SERVER_INFO;
@@ -534,10 +658,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 +679,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 +701,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 +726,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_);
@@ -616,10 +755,16 @@ int QuicStreamFactory::Job::DoConnect() {
     return ERR_QUIC_HANDSHAKE_FAILED;
   }
 
+  if (rv == ERR_IO_PENDING) {
+    crypto_connect_io_pending_ = true;
+  }
+
   return rv;
 }
 
 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 +774,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)
@@ -654,11 +800,13 @@ int QuicStreamFactory::Job::DoConnectComplete(int rv) {
     session_->connection()->CloseConnection(
         QUIC_CONNECTION_IP_POOLED, "An active session exists for the given IP.",
         ConnectionCloseBehavior::SEND_CONNECTION_CLOSE_PACKET);
+    session_was_active_ = true;
     session_ = nullptr;
     return OK;
   }
 
   factory_->ActivateSession(key_, session_);
+  session_was_active_ = true;
 
   return OK;
 }
@@ -701,6 +849,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 +918,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,11 +1122,18 @@ 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()) {
       QuicChromiumClientSession* session = active_sessions_.begin()->second;
+      QuicServerId server_id = session->server_id();
       OnSessionGoingAway(session);
+      // possible place where active_session is removed; but active_jobs not.
+      DCHECK(!HasActiveSession(server_id));
+      DCHECK(!HasActiveJob(server_id));
       // TODO(rch): actually close the session?
     }
   }
@@ -989,6 +1148,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 +1165,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 +1175,23 @@ 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());
+      active_jobs_[server_id].begin()->first->LogCurrentStatus();
+    }
+    // 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));
+    net_log.AddEvent(
+        NetLogEventType::QUIC_STREAM_FACTORY_REQUEST_BOUND_TO_ACTIVE_JOB,
+        NetLog::BoolCallback("active_jobs_exist", true));
     return ERR_IO_PENDING;
   }
 
@@ -1022,6 +1202,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 +1231,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 +1246,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));
+
+    // 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 +1284,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;
 }
 
@@ -1123,6 +1351,10 @@ bool QuicStreamFactory::OnResolution(const QuicSessionKey& key,
     for (QuicChromiumClientSession* session : sessions) {
       if (!session->CanPool(server_id.host(), server_id.privacy_mode()))
         continue;
+      std::string server_id_string = server_id.ToString();
+      quic_net_log_.AddEvent(
+          NetLogEventType::QUIC_STREAM_FACTORY_ACTIVE_SESSION_INSERTION,
+          NetLog::StringCallback("server_id", &server_id_string));
       active_sessions_[server_id] = session;
       session_aliases_[session].insert(key);
       return true;
@@ -1135,17 +1367,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 +1427,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) {
@@ -1237,6 +1505,10 @@ void QuicStreamFactory::OnSessionGoingAway(QuicChromiumClientSession* session) {
     if (session->goaway_received())
       gone_away_aliases_.insert(*it);
 
+    std::string server_id_string = server_id.ToString();
+    quic_net_log_.AddEvent(
+        NetLogEventType::QUIC_STREAM_FACTORY_ACTIVE_SESSION_DELETION,
+        NetLog::StringCallback("server_id", &server_id_string));
     active_sessions_.erase(server_id);
     ProcessGoingAwaySession(session, server_id, true);
   }
@@ -1578,8 +1850,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(
@@ -1758,6 +2040,10 @@ void QuicStreamFactory::ActivateSession(const QuicSessionKey& key,
   const QuicServerId& server_id(key.server_id());
   DCHECK(!HasActiveSession(server_id));
   UMA_HISTOGRAM_COUNTS("Net.QuicActiveSessions", active_sessions_.size());
+  std::string server_id_string = server_id.ToString();
+  quic_net_log_.AddEvent(
+      NetLogEventType::QUIC_STREAM_FACTORY_ACTIVE_SESSION_INSERTION,
+      NetLog::StringCallback("server_id", &server_id_string));
   active_sessions_[server_id] = session;
   session_aliases_[session].insert(key);
   const IPEndPoint peer_address =