[DO NOT SUBMIT, PATCH on commit 7fa349e632a44c152b05ca6a66ade5f2e5b3f139]

net/quic/chromium/quic_stream_factory.cc

 // Copyright (c) 2012 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/quic/chromium/quic_stream_factory.h"
 
 #include <algorithm>
 #include <tuple>
 #include <utility>
 
@@ skipping 102 matching lines @@
 }
 
 std::unique_ptr<base::Value> NetLogQuicConnectionMigrationSuccessCallback(
     QuicConnectionId connection_id,
     NetLogCaptureMode capture_mode) {
   std::unique_ptr<base::DictionaryValue> dict(new base::DictionaryValue());
   dict->SetString("connection_id", base::Uint64ToString(connection_id));
   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:
   ScopedConnectionMigrationEventLog(NetLog* net_log, std::string trigger)
       : net_log_(NetLogWithSource::Make(
             net_log,
             NetLogSourceType::QUIC_CONNECTION_MIGRATION)) {
     net_log_.BeginEvent(
         NetLogEventType::QUIC_CONNECTION_MIGRATION_TRIGGERED,
         base::Bind(&NetLogQuicConnectionMigrationTriggerCallback, trigger));
@@ skipping 202 matching lines @@
   void RunAuxilaryJob();
 
   void Cancel();
 
   void CancelWaitForDataReadyCallback();
 
   const QuicSessionKey& key() const { return key_; }
 
   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,
     STATE_RESOLVE_HOST,
     STATE_RESOLVE_HOST_COMPLETE,
     STATE_LOAD_SERVER_INFO,
     STATE_LOAD_SERVER_INFO_COMPLETE,
     STATE_CONNECT,
     STATE_RESUME_CONNECT,
     STATE_CONNECT_COMPLETE,
   };
+
+  bool session_was_active_;
+  bool crypto_connect_io_pending_;
+
   IoState io_state_;
 
   QuicStreamFactory* factory_;
   HostResolver* host_resolver_;
   std::unique_ptr<HostResolver::Request> request_;
   QuicSessionKey key_;
   int cert_verify_flags_;
   bool was_alternative_service_recently_broken_;
   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_;
   AddressList address_list_;
   base::TimeTicks dns_resolution_start_time_;
   base::TimeTicks dns_resolution_end_time_;
   base::WeakPtrFactory<Job> weak_factory_;
   DISALLOW_COPY_AND_ASSIGN(Job);
 };
 
 QuicStreamFactory::Job::Job(QuicStreamFactory* factory,
                             HostResolver* host_resolver,
                             const QuicSessionKey& key,
                             bool was_alternative_service_recently_broken,
                             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),
       cert_verify_flags_(cert_verify_flags),
       was_alternative_service_recently_broken_(
           was_alternative_service_recently_broken),
       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),
       cert_verify_flags_(0),                            // unused
       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();
 }
 
 int QuicStreamFactory::Job::Run(const CompletionCallback& callback) {
   int rv = DoLoop(OK);
   if (rv == ERR_IO_PENDING)
     callback_ = 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 {
     IoState state = io_state_;
     io_state_ = STATE_NONE;
     switch (state) {
       case STATE_RESOLVE_HOST:
         CHECK_EQ(OK, rv);
         rv = DoResolveHost();
         break;
@@ skipping 34 matching lines @@
 }
 
 void QuicStreamFactory::Job::RunAuxilaryJob() {
   int rv = Run(base::Bind(&QuicStreamFactory::OnJobComplete,
                           base::Unretained(factory_), this));
   if (rv != ERR_IO_PENDING)
     factory_->OnJobComplete(this, rv);
 }
 
 void QuicStreamFactory::Job::Cancel() {
+  job_net_log_.AddEvent(NetLogEventType::QUIC_STREAM_FACTORY_JOB_CANCELLED);
   callback_.Reset();
   if (session_)
     session_->connection()->CloseConnection(
         QUIC_CONNECTION_CANCELLED, "New job canceled.",
         ConnectionCloseBehavior::SEND_CONNECTION_CLOSE_PACKET);
 }
 
 void QuicStreamFactory::Job::CancelWaitForDataReadyCallback() {
   // If we are waiting for WaitForDataReadyCallback, then cancel the callback.
   if (io_state_ != STATE_LOAD_SERVER_INFO_COMPLETE)
     return;
   server_info_->CancelWaitForDataReadyCallback();
   OnIOComplete(OK);
 }
 
 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_)
     server_info_->Start();
 
   io_state_ = STATE_RESOLVE_HOST_COMPLETE;
   return host_resolver_->Resolve(
       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;
 
   DCHECK(!factory_->HasActiveSession(key_.server_id()));
 
   // 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;
   else
     io_state_ = STATE_CONNECT;
   return OK;
 }
 
 int QuicStreamFactory::Job::DoLoadServerInfo() {
   io_state_ = STATE_LOAD_SERVER_INFO_COMPLETE;
 
   DCHECK(server_info_);
 
   // 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(
                           key_.server_id())) /
                      1000),
                  kMaxLoadServerInfoTimeoutMs);
     if (load_server_info_timeout_ms > 0) {
       factory_->task_runner_->PostDelayedTask(
           FROM_HERE,
           base::Bind(&QuicStreamFactory::Job::CancelWaitForDataReadyCallback,
                      GetWeakPtr()),
           base::TimeDelta::FromMilliseconds(load_server_info_timeout_ms));
     }
   }
 
+  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;
 }
 
 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();
 
   if (started_another_job_ &&
       (!server_info_ || server_info_->state().server_config.empty() ||
        !factory_->CryptoConfigCacheIsEmpty(key_.server_id()))) {
     // If we have started another job and if we didn't load the server config
     // from the disk cache or if we have received a new server config from the
     // server, then cancel the current job.
     io_state_ = STATE_NONE;
     return ERR_CONNECTION_CLOSED;
   }
 
   io_state_ = STATE_CONNECT;
   return OK;
 }
 
 int QuicStreamFactory::Job::DoConnect() {
   io_state_ = STATE_CONNECT_COMPLETE;
 
   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_);
     return rv;
   }
 
   if (!session_->connection()->connected())
     return ERR_CONNECTION_CLOSED;
 
   session_->StartReading();
   if (!session_->connection()->connected())
     return ERR_QUIC_PROTOCOL_ERROR;
 
   rv = session_->CryptoConnect(
       base::Bind(&QuicStreamFactory::Job::OnIOComplete, GetWeakPtr()));
 
   if (!session_->connection()->connected() &&
       session_->error() == QUIC_PROOF_INVALID) {
     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(
       base::Bind(&QuicStreamFactory::Job::OnIOComplete, GetWeakPtr()));
 
   return rv;
 }
 
 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)
       return ERR_QUIC_HANDSHAKE_FAILED;
     // The handshake was rejected statelessly, so create another connection
     // to resume the handshake.
     io_state_ = STATE_CONNECT;
     return OK;
   }
 
   if (was_alternative_service_recently_broken_)
     UMA_HISTOGRAM_BOOLEAN("Net.QuicSession.ConnectAfterBroken", rv == OK);
 
   if (rv != OK)
     return rv;
 
   DCHECK(!factory_->HasActiveSession(key_.server_id()));
   // There may well now be an active session for this IP.  If so, use the
   // existing session instead.
   AddressList address(
       session_->connection()->peer_address().impl().socket_address());
   if (factory_->OnResolution(key_, address)) {
     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;
 }
 
 QuicStreamRequest::QuicStreamRequest(QuicStreamFactory* factory)
     : factory_(factory) {}
 
 QuicStreamRequest::~QuicStreamRequest() {
   if (factory_ && !callback_.is_null())
     factory_->CancelRequest(this);
@@ skipping 22 matching lines @@
     DCHECK(session_);
   return rv;
 }
 
 void QuicStreamRequest::SetSession(QuicChromiumClientSession* session) {
   DCHECK(session);
   session_ = session->GetWeakPtr();
 }
 
 void QuicStreamRequest::OnRequestComplete(int rv) {
+  net_log_.EndEvent(NetLogEventType::QUIC_STREAM_FACTORY_CREATE_HTTP_STREAM);
   factory_ = nullptr;
   callback_.Run(rv);
 }
 
 base::TimeDelta QuicStreamRequest::GetTimeDelayForWaitingJob() const {
   if (!factory_)
     return base::TimeDelta();
   return factory_->GetTimeDelayForWaitingJob(server_id_);
 }
 
@@ skipping 48 matching lines @@
     bool migrate_sessions_early,
     bool allow_server_migration,
     bool force_hol_blocking,
     bool race_cert_verification,
     bool do_not_fragment,
     bool estimate_initial_rtt,
     const QuicTagVector& connection_options,
     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),
       push_delegate_(nullptr),
       proxy_delegate_(proxy_delegate),
       transport_security_state_(transport_security_state),
       cert_transparency_verifier_(cert_transparency_verifier),
       quic_crypto_client_stream_factory_(quic_crypto_client_stream_factory),
       random_generator_(random_generator),
       clock_(clock),
@@ skipping 181 matching lines @@
   return false;
 }
 
 int QuicStreamFactory::Create(const QuicServerId& server_id,
                               const HostPortPair& destination,
                               int cert_verify_flags,
                               const GURL& url,
                               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?
     }
   }
   DCHECK(server_id.host_port_pair().Equals(HostPortPair::FromURL(url)));
   // Enforce session affinity for promised streams.
   QuicClientPromisedInfo* promised =
       push_promise_index_.GetPromised(url.spec());
   if (promised) {
     QuicChromiumClientSession* session =
         static_cast<QuicChromiumClientSession*>(promised->session());
     DCHECK(session);
     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
     // request comes in with a mismatched privacy mode, consider the
     // promise borked.
     promised->Cancel();
   }
 
   // Use active session for |server_id| if such exists.
   // TODO(rtenneti): crbug.com/498823 - delete active_sessions_.empty() checks.
   if (!active_sessions_.empty()) {
     SessionMap::iterator it = active_sessions_.find(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;
     }
   }
 
   // Associate with active job to |server_id| if such exists.
   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;
   }
 
   // Pool to active session to |destination| if possible.
   if (!active_sessions_.empty() && !disable_connection_pooling_) {
     for (const auto& key_value : active_sessions_) {
       QuicChromiumClientSession* session = key_value.second;
       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;
       }
     }
   }
 
   // TODO(rtenneti): |task_runner_| is used by the Job. Initialize task_runner_
   // in the constructor after WebRequestActionWithThreadsTest.* tests are fixed.
   if (!task_runner_)
     task_runner_ = base::ThreadTaskRunnerHandle::Get().get();
 
   std::unique_ptr<QuicServerInfo> quic_server_info;
   if (quic_server_info_factory_.get()) {
     bool load_from_disk_cache = !disable_disk_cache_;
     MaybeInitialize();
     if (!base::ContainsKey(quic_supported_servers_at_startup_, destination)) {
       // If there is no entry for QUIC, consider that as a new server and
       // don't wait for Cache thread to load the data for that server.
       load_from_disk_cache = false;
     }
     if (load_from_disk_cache && CryptoConfigCacheIsEmpty(server_id))
       quic_server_info = quic_server_info_factory_->GetForServer(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);
   int rv = job->Run(base::Bind(&QuicStreamFactory::OnJobComplete,
                                base::Unretained(this), job.get()));
   if (rv == ERR_IO_PENDING) {
     active_requests_[request] = 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())
       return ERR_QUIC_PROTOCOL_ERROR;
     SessionMap::iterator it = active_sessions_.find(server_id);
     DCHECK(it != active_sessions_.end());
     if (it == active_sessions_.end())
       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;
 }
 
 QuicStreamFactory::QuicSessionKey::QuicSessionKey(
     const HostPortPair& destination,
     const QuicServerId& server_id)
     : destination_(destination), server_id_(server_id) {}
 
 bool QuicStreamFactory::QuicSessionKey::operator<(
     const QuicSessionKey& other) const {
@@ skipping 31 matching lines @@
   if (disable_connection_pooling_)
     return false;
   for (const IPEndPoint& address : address_list) {
     if (!base::ContainsKey(ip_aliases_, address))
       continue;
 
     const SessionSet& sessions = ip_aliases_[address];
     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;
     }
   }
   return false;
 }
 
 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);
 
     if (!job_requests_map_[server_id].empty()) {
       SessionMap::iterator session_it = active_sessions_.find(server_id);
       DCHECK(session_it != active_sessions_.end());
       QuicChromiumClientSession* session = session_it->second;
       for (QuicStreamRequest* request : job_requests_map_[server_id]) {
         DCHECK(request->server_id() == server_id);
         // Do not notify |request| yet.
         request->SetSession(session);
       }
     }
   }
 
   while (!job_requests_map_[server_id].empty()) {
     RequestSet::iterator it = job_requests_map_[server_id].begin();
     QuicStreamRequest* request = *it;
     job_requests_map_[server_id].erase(it);
     active_requests_.erase(request);
     // Even though we're invoking callbacks here, we don't need to worry
     // about |this| being deleted, because the factory is owned by the
     // profile which can not be deleted via callbacks.
     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) {
   active_cert_verifier_jobs_.erase(job->server_id());
 }
 
 std::unique_ptr<QuicHttpStream> QuicStreamFactory::CreateFromSession(
     QuicChromiumClientSession* session) {
   return std::unique_ptr<QuicHttpStream>(
       new QuicHttpStream(session->GetWeakPtr()));
@@ skipping 36 matching lines @@
   for (AliasSet::const_iterator it = aliases.begin(); it != aliases.end();
        ++it) {
     const QuicServerId& server_id = it->server_id();
     DCHECK(active_sessions_.count(server_id));
     DCHECK_EQ(session, active_sessions_[server_id]);
     // Track sessions which have recently gone away so that we can disable
     // port suggestions.
     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);
   }
   ProcessGoingAwaySession(session, all_sessions_[session].server_id(), false);
   if (!aliases.empty()) {
     DCHECK(base::ContainsKey(session_peer_ip_, session));
     const IPEndPoint peer_address = session_peer_ip_[session];
     ip_aliases_[peer_address].erase(session);
     if (ip_aliases_[peer_address].empty())
       ip_aliases_.erase(peer_address);
@@ skipping 321 matching lines @@
   CloseAllSessions(ERR_CERT_DATABASE_CHANGED, QUIC_CONNECTION_CANCELLED);
 }
 
 bool QuicStreamFactory::HasActiveSession(const QuicServerId& server_id) const {
   // TODO(rtenneti): crbug.com/498823 - delete active_sessions_.empty() check.
   if (active_sessions_.empty())
     return false;
   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(
     const QuicServerId& server_id) const {
   return base::ContainsKey(active_cert_verifier_jobs_, server_id);
 }
 
 int QuicStreamFactory::ConfigureSocket(DatagramClientSocket* socket,
                                        IPEndPoint addr,
                                        NetworkHandle network) {
@@ skipping 158 matching lines @@
     return ERR_CONNECTION_CLOSED;
   }
   return OK;
 }
 
 void QuicStreamFactory::ActivateSession(const QuicSessionKey& key,
                                         QuicChromiumClientSession* session) {
   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 =
       session->connection()->peer_address().impl().socket_address();
   DCHECK(!base::ContainsKey(ip_aliases_[peer_address], session));
   ip_aliases_[peer_address].insert(session);
   DCHECK(!base::ContainsKey(session_peer_ip_, session));
   session_peer_ip_[session] = peer_address;
 }
 
@@ skipping 212 matching lines @@
 void QuicStreamFactory::OpenFactory() {
   status_ = OPEN;
 }
 
 void QuicStreamFactory::MaybeClearConsecutiveDisabledCount() {
   if (status_ == OPEN)
     consecutive_disabled_count_ = 0;
 }
 
 }  // namespace net