Add net-log entries when HttpStream jobs are forced to wait, and when they're delayed and resumed.

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/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);
-}
-
 HttpStreamFactoryImpl::JobController::JobController(
     HttpStreamFactoryImpl* factory,
     HttpStreamRequest::Delegate* delegate,
     HttpNetworkSession* session,
     JobFactory* job_factory)
     : factory_(factory),
       session_(session),
       job_factory_(job_factory),
       request_(nullptr),
       delegate_(delegate),
@@ skipping 459 matching lines @@
 void HttpStreamFactoryImpl::JobController::AddConnectionAttemptsToRequest(
     Job* job,
     const ConnectionAttempts& attempts) {
   if (is_preconnect_ || (job_bound_ && bound_job_ != job))
     return;
 
   DCHECK(request_);
   request_->AddConnectionAttempts(attempts);
 }
 
+void HttpStreamFactoryImpl::JobController::ResumeMainJobLater(
+    const base::TimeDelta& delay) {
+  net_log_.AddEvent(NetLogEventType::HTTP_STREAM_JOB_DELAYED,
+                    NetLog::Int64Callback("delay", delay.InMilliseconds()));
+  base::ThreadTaskRunnerHandle::Get()->PostDelayedTask(
+      FROM_HERE,
+      base::Bind(&HttpStreamFactoryImpl::JobController::ResumeMainJob,
+                 ptr_factory_.GetWeakPtr()),
+      delay);
+}
+
 void HttpStreamFactoryImpl::JobController::ResumeMainJob() {
   main_job_->net_log().AddEvent(
-      NetLogEventType::HTTP_STREAM_JOB_DELAYED,
-      base::Bind(&NetLogHttpStreamJobDelayCallback, main_job_wait_time_));
+      NetLogEventType::HTTP_STREAM_JOB_RESUMED,
+      NetLog::Int64Callback("delay", main_job_wait_time_.InMilliseconds()));
 
   main_job_->Resume();
   main_job_wait_time_ = base::TimeDelta();
 }
 
 void HttpStreamFactoryImpl::JobController::MaybeResumeMainJob(
     Job* job,
     const base::TimeDelta& delay) {
   DCHECK(job == main_job_.get() || job == alternative_job_.get());
 
   if (!main_job_is_blocked_ || job != alternative_job_.get() || !main_job_)
     return;
 
   main_job_is_blocked_ = false;
 
   if (!main_job_->is_waiting())
     return;
 
-  base::ThreadTaskRunnerHandle::Get()->PostDelayedTask(
-      FROM_HERE,
-      base::Bind(&HttpStreamFactoryImpl::JobController::ResumeMainJob,
-                 ptr_factory_.GetWeakPtr()),
-      main_job_wait_time_);
+  ResumeMainJobLater(main_job_wait_time_);
 }
 
 void HttpStreamFactoryImpl::JobController::OnConnectionInitialized(Job* job,
                                                                    int rv) {
   if (rv != OK) {
     // Resume the main job as there's an error raised in connection
     // initiation.
     return MaybeResumeMainJob(job, main_job_wait_time_);
   }
 }
 
 bool HttpStreamFactoryImpl::JobController::ShouldWait(Job* job) {
   // The alternative job never waits.
   if (job == alternative_job_.get())
     return false;
 
   if (main_job_is_blocked_)
     return true;
 
   if (main_job_wait_time_.is_zero())
     return false;
 
-  base::ThreadTaskRunnerHandle::Get()->PostDelayedTask(
-      FROM_HERE,
-      base::Bind(&HttpStreamFactoryImpl::JobController::ResumeMainJob,
-                 ptr_factory_.GetWeakPtr()),
-      main_job_wait_time_);
-
+  ResumeMainJobLater(main_job_wait_time_);
   return true;
 }
 
 void HttpStreamFactoryImpl::JobController::SetSpdySessionKey(
     Job* job,
     const SpdySessionKey& spdy_session_key) {
   if (is_preconnect_ || (job_bound_ && bound_job_ != job))
     return;
 
   DCHECK(request_);
@@ skipping 514 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