LoadTiming implementation in net, part 1.

net/socket/client_socket_pool_base_unittest.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/socket/client_socket_pool_base.h"
 
 #include <vector>
 
 #include "base/bind.h"
 #include "base/bind_helpers.h"
 #include "base/callback.h"
 #include "base/compiler_specific.h"
 #include "base/memory/ref_counted.h"
 #include "base/memory/scoped_vector.h"
 #include "base/memory/weak_ptr.h"
 #include "base/message_loop.h"
+#include "base/run_loop.h"
 #include "base/stringprintf.h"
 #include "base/string_number_conversions.h"
 #include "base/threading/platform_thread.h"
 #include "base/values.h"
+#include "net/base/load_timing_info.h"
 #include "net/base/net_errors.h"
 #include "net/base/net_log.h"
 #include "net/base/net_log_unittest.h"
 #include "net/base/request_priority.h"
 #include "net/base/test_completion_callback.h"
 #include "net/http/http_response_headers.h"
 #include "net/socket/client_socket_factory.h"
 #include "net/socket/client_socket_handle.h"
 #include "net/socket/client_socket_pool_histograms.h"
 #include "net/socket/socket_test_util.h"
 #include "net/socket/stream_socket.h"
 #include "testing/gmock/include/gmock/gmock.h"
 #include "testing/gtest/include/gtest/gtest.h"
 
 using ::testing::Invoke;
 using ::testing::Return;
 
 namespace net {
 
 namespace {
 
 const int kDefaultMaxSockets = 4;
 const int kDefaultMaxSocketsPerGroup = 2;
 const net::RequestPriority kDefaultPriority = MEDIUM;
 
+// Make sure |handle| sets load times correctly when it has been assigned a
+// reused socket.
+void TestLoadTimingInfoConnectedReused(const ClientSocketHandle& handle) {
+  LoadTimingInfo load_timing_info;
+  // Only pass true in as |is_reused|, as in general, HttpStream types should
+  // have stricter concepts of reuse than socket pools.
+  EXPECT_TRUE(handle.GetLoadTimingInfo(true, &load_timing_info));
+
+  EXPECT_EQ(true, load_timing_info.socket_reused);
+  EXPECT_NE(NetLog::Source::kInvalidId, load_timing_info.socket_log_id);
+
+  EXPECT_TRUE(load_timing_info.connect_start.is_null());
+  EXPECT_TRUE(load_timing_info.connect_end.is_null());
+  EXPECT_TRUE(load_timing_info.dns_start.is_null());
+  EXPECT_TRUE(load_timing_info.dns_end.is_null());
+  EXPECT_TRUE(load_timing_info.ssl_start.is_null());
+  EXPECT_TRUE(load_timing_info.ssl_end.is_null());
+  EXPECT_TRUE(load_timing_info.proxy_resolve_start.is_null());
+  EXPECT_TRUE(load_timing_info.proxy_resolve_end.is_null());
+  EXPECT_TRUE(load_timing_info.send_start.is_null());
+  EXPECT_TRUE(load_timing_info.send_end.is_null());
+  EXPECT_TRUE(load_timing_info.receive_headers_end.is_null());
+}
+
+// Make sure |handle| sets load times correctly when it has been assigned a
+// fresh socket.  Also runs TestLoadTimingInfoConnectedReused, since the owner
+// of a connection where |is_reused| is false may consider the connection
+// reused.
+void TestLoadTimingInfoConnectedNotReused(const ClientSocketHandle& handle) {
+  EXPECT_FALSE(handle.is_reused());
+
+  LoadTimingInfo load_timing_info;
+  EXPECT_TRUE(handle.GetLoadTimingInfo(false, &load_timing_info));
+
+  EXPECT_FALSE(load_timing_info.socket_reused);
+  EXPECT_NE(NetLog::Source::kInvalidId, load_timing_info.socket_log_id);
+
+  EXPECT_FALSE(load_timing_info.connect_start.is_null());
+  EXPECT_LE(load_timing_info.connect_start, load_timing_info.connect_end);
+  EXPECT_TRUE(load_timing_info.dns_start.is_null());
+  EXPECT_TRUE(load_timing_info.dns_end.is_null());
+  EXPECT_TRUE(load_timing_info.ssl_start.is_null());
+  EXPECT_TRUE(load_timing_info.ssl_end.is_null());
+  EXPECT_TRUE(load_timing_info.proxy_resolve_start.is_null());
+  EXPECT_TRUE(load_timing_info.proxy_resolve_end.is_null());
+  EXPECT_TRUE(load_timing_info.send_start.is_null());
+  EXPECT_TRUE(load_timing_info.send_end.is_null());
+  EXPECT_TRUE(load_timing_info.receive_headers_end.is_null());
+
+  TestLoadTimingInfoConnectedReused(handle);
+}
+
+// Make sure |handle| sets load times correctly, in the case that it does not
+// currently have a socket.
+void TestLoadTimingInfoNotConnected(const ClientSocketHandle& handle) {
+  // Should only be set to true once a socket is assigned, if at all.
+  EXPECT_FALSE(handle.is_reused());
+
+  LoadTimingInfo load_timing_info;
+  EXPECT_FALSE(handle.GetLoadTimingInfo(false, &load_timing_info));
+
+  EXPECT_FALSE(load_timing_info.socket_reused);
+  EXPECT_EQ(NetLog::Source::kInvalidId, load_timing_info.socket_log_id);
+
+  EXPECT_TRUE(load_timing_info.connect_start.is_null());
+  EXPECT_TRUE(load_timing_info.connect_end.is_null());
+  EXPECT_TRUE(load_timing_info.dns_start.is_null());
+  EXPECT_TRUE(load_timing_info.dns_end.is_null());
+  EXPECT_TRUE(load_timing_info.ssl_start.is_null());
+  EXPECT_TRUE(load_timing_info.ssl_end.is_null());
+  EXPECT_TRUE(load_timing_info.proxy_resolve_start.is_null());
+  EXPECT_TRUE(load_timing_info.proxy_resolve_end.is_null());
+  EXPECT_TRUE(load_timing_info.send_start.is_null());
+  EXPECT_TRUE(load_timing_info.send_end.is_null());
+  EXPECT_TRUE(load_timing_info.receive_headers_end.is_null());
+}
+
 class TestSocketParams : public base::RefCounted<TestSocketParams> {
  public:
   TestSocketParams() : ignore_limits_(false) {}
 
   void set_ignore_limits(bool ignore_limits) {
     ignore_limits_ = ignore_limits;
   }
   bool ignore_limits() { return ignore_limits_; }
 
  private:
   friend class base::RefCounted<TestSocketParams>;
   ~TestSocketParams() {}
 
   bool ignore_limits_;
 };
 typedef ClientSocketPoolBase<TestSocketParams> TestClientSocketPoolBase;
 
 class MockClientSocket : public StreamSocket {
  public:
-  MockClientSocket() : connected_(false), was_used_to_convey_data_(false),
-                       num_bytes_read_(0) {}
+  explicit MockClientSocket(net::NetLog* net_log)
+      : connected_(false),
+        net_log_(BoundNetLog::Make(net_log, net::NetLog::SOURCE_SOCKET)),
+        was_used_to_convey_data_(false),
+        num_bytes_read_(0) {
+  }
 
   // Socket implementation.
   virtual int Read(
       IOBuffer* /* buf */, int len,
       const CompletionCallback& /* callback */) OVERRIDE {
     num_bytes_read_ += len;
     return len;
   }
 
   virtual int Write(
@@ skipping 154 matching lines @@
     }
   }
 
  private:
   // ConnectJob implementation.
 
   virtual int ConnectInternal() {
     AddressList ignored;
     client_socket_factory_->CreateTransportClientSocket(
         ignored, NULL, net::NetLog::Source());
-    set_socket(new MockClientSocket());
+    set_socket(new MockClientSocket(net_log().net_log()));
     switch (job_type_) {
       case kMockJob:
         return DoConnect(true /* successful */, false /* sync */,
                          false /* recoverable */);
       case kMockFailingJob:
         return DoConnect(false /* error */, false /* sync */,
                          false /* recoverable */);
       case kMockPendingJob:
         set_load_state(LOAD_STATE_CONNECTING);
 
@@ skipping 114 matching lines @@
   base::WeakPtrFactory<TestConnectJob> weak_factory_;
   LoadState load_state_;
   bool store_additional_error_state_;
 
   DISALLOW_COPY_AND_ASSIGN(TestConnectJob);
 };
 
 class TestConnectJobFactory
     : public TestClientSocketPoolBase::ConnectJobFactory {
  public:
-  explicit TestConnectJobFactory(MockClientSocketFactory* client_socket_factory)
+  TestConnectJobFactory(MockClientSocketFactory* client_socket_factory,
+                        NetLog* net_log)
       : job_type_(TestConnectJob::kMockJob),
         job_types_(NULL),
-        client_socket_factory_(client_socket_factory) {}
+        client_socket_factory_(client_socket_factory),
+        net_log_(net_log) {
+}
 
   virtual ~TestConnectJobFactory() {}
 
   void set_job_type(TestConnectJob::JobType job_type) { job_type_ = job_type; }
 
   void set_job_types(std::list<TestConnectJob::JobType>* job_types) {
     job_types_ = job_types;
     CHECK(!job_types_->empty());
   }
 
@@ skipping 12 matching lines @@
     if (job_types_ && !job_types_->empty()) {
       job_type = job_types_->front();
       job_types_->pop_front();
     }
     return new TestConnectJob(job_type,
                               group_name,
                               request,
                               timeout_duration_,
                               delegate,
                               client_socket_factory_,
-                              NULL);
+                              net_log_);
   }
 
   virtual base::TimeDelta ConnectionTimeout() const {
     return timeout_duration_;
   }
 
  private:
   TestConnectJob::JobType job_type_;
   std::list<TestConnectJob::JobType>* job_types_;
   base::TimeDelta timeout_duration_;
   MockClientSocketFactory* const client_socket_factory_;
+  NetLog* net_log_;
 
   DISALLOW_COPY_AND_ASSIGN(TestConnectJobFactory);
 };
 
 class TestClientSocketPool : public ClientSocketPool {
  public:
   TestClientSocketPool(
       int max_sockets,
       int max_sockets_per_group,
       ClientSocketPoolHistograms* histograms,
@@ skipping 197 matching lines @@
         max_sockets_per_group,
         ClientSocketPool::unused_idle_socket_timeout(),
         ClientSocketPool::used_idle_socket_timeout());
   }
 
   void CreatePoolWithIdleTimeouts(
       int max_sockets, int max_sockets_per_group,
       base::TimeDelta unused_idle_socket_timeout,
       base::TimeDelta used_idle_socket_timeout) {
     DCHECK(!pool_.get());
-    connect_job_factory_ = new TestConnectJobFactory(&client_socket_factory_);
+    connect_job_factory_ = new TestConnectJobFactory(&client_socket_factory_,
+                                                     &net_log_);
     pool_.reset(new TestClientSocketPool(max_sockets,
                                          max_sockets_per_group,
                                          &histograms_,
                                          unused_idle_socket_timeout,
                                          used_idle_socket_timeout,
                                          connect_job_factory_));
   }
 
   int StartRequest(const std::string& group_name,
                    net::RequestPriority priority) {
@@ skipping 12 matching lines @@
 
   void ReleaseAllConnections(ClientSocketPoolTest::KeepAlive keep_alive) {
     test_base_.ReleaseAllConnections(keep_alive);
   }
 
   TestSocketRequest* request(int i) { return test_base_.request(i); }
   size_t requests_size() const { return test_base_.requests_size(); }
   ScopedVector<TestSocketRequest>* requests() { return test_base_.requests(); }
   size_t completion_count() const { return test_base_.completion_count(); }
 
+  CapturingNetLog net_log_;
   bool connect_backup_jobs_enabled_;
   bool cleanup_timer_enabled_;
   MockClientSocketFactory client_socket_factory_;
   TestConnectJobFactory* connect_job_factory_;
   scoped_refptr<TestSocketParams> params_;
   ClientSocketPoolHistograms histograms_;
   scoped_ptr<TestClientSocketPool> pool_;
   ClientSocketPoolTest test_base_;
 };
 
@@ skipping 123 matching lines @@
   EXPECT_TRUE(LogContainsEndEvent(
       entries, 5, NetLog::TYPE_SOCKET_POOL_CONNECT_JOB));
 }
 
 TEST_F(ClientSocketPoolBaseTest, BasicSynchronous) {
   CreatePool(kDefaultMaxSockets, kDefaultMaxSocketsPerGroup);
 
   TestCompletionCallback callback;
   ClientSocketHandle handle;
   CapturingBoundNetLog log;
+  TestLoadTimingInfoNotConnected(handle);
 
   EXPECT_EQ(OK,
             handle.Init("a",
                         params_,
                         kDefaultPriority,
                         callback.callback(),
                         pool_.get(),
                         log.bound()));
   EXPECT_TRUE(handle.is_initialized());
   EXPECT_TRUE(handle.socket());
+  TestLoadTimingInfoConnectedNotReused(handle);
+
   handle.Reset();
+  TestLoadTimingInfoNotConnected(handle);
 
   CapturingNetLog::CapturedEntryList entries;
   log.GetEntries(&entries);
 
   EXPECT_EQ(4u, entries.size());
   EXPECT_TRUE(LogContainsBeginEvent(
       entries, 0, NetLog::TYPE_SOCKET_POOL));
   EXPECT_TRUE(LogContainsEvent(
       entries, 1, NetLog::TYPE_SOCKET_POOL_BOUND_TO_CONNECT_JOB,
       NetLog::PHASE_NONE));
@@ skipping 20 matching lines @@
   EXPECT_EQ(ERR_CONNECTION_FAILED,
             handle.Init("a",
                         params_,
                         kDefaultPriority,
                         callback.callback(),
                         pool_.get(),
                         log.bound()));
   EXPECT_FALSE(handle.socket());
   EXPECT_FALSE(handle.is_ssl_error());
   EXPECT_TRUE(handle.ssl_error_response_info().headers.get() == NULL);
+  TestLoadTimingInfoNotConnected(handle);
 
   CapturingNetLog::CapturedEntryList entries;
   log.GetEntries(&entries);
 
   EXPECT_EQ(3u, entries.size());
   EXPECT_TRUE(LogContainsBeginEvent(
       entries, 0, NetLog::TYPE_SOCKET_POOL));
   EXPECT_TRUE(LogContainsEvent(
       entries, 1, NetLog::TYPE_SOCKET_POOL_BOUND_TO_CONNECT_JOB,
       NetLog::PHASE_NONE));
@@ skipping 749 matching lines @@
   rv = handle.Init("a",
                    params_,
                    kDefaultPriority,
                    callback.callback(),
                    pool_.get(),
                    BoundNetLog());
   EXPECT_EQ(ERR_IO_PENDING, rv);
   EXPECT_EQ(OK, callback.WaitForResult());
 
   EXPECT_FALSE(handle.is_reused());
+  TestLoadTimingInfoConnectedNotReused(handle);
   EXPECT_EQ(2, client_socket_factory_.allocation_count());
 }
 
 // Regression test for http://crbug.com/17985.
 TEST_F(ClientSocketPoolBaseTest, GroupWithPendingRequestsIsNotEmpty) {
   const int kMaxSockets = 3;
   const int kMaxSocketsPerGroup = 2;
   CreatePool(kMaxSockets, kMaxSocketsPerGroup);
 
   const RequestPriority kHighPriority = HIGHEST;
@@ skipping 34 matching lines @@
   TestCompletionCallback callback;
   CapturingBoundNetLog log;
   int rv = handle.Init("a",
                        params_,
                        LOWEST,
                        callback.callback(),
                        pool_.get(),
                        log.bound());
   EXPECT_EQ(ERR_IO_PENDING, rv);
   EXPECT_EQ(LOAD_STATE_CONNECTING, pool_->GetLoadState("a", &handle));
+  TestLoadTimingInfoNotConnected(handle);
+
   EXPECT_EQ(OK, callback.WaitForResult());
   EXPECT_TRUE(handle.is_initialized());
   EXPECT_TRUE(handle.socket());
+  TestLoadTimingInfoConnectedNotReused(handle);
+
   handle.Reset();
+  TestLoadTimingInfoNotConnected(handle);
 
   CapturingNetLog::CapturedEntryList entries;
   log.GetEntries(&entries);
 
   EXPECT_EQ(4u, entries.size());
   EXPECT_TRUE(LogContainsBeginEvent(
       entries, 0, NetLog::TYPE_SOCKET_POOL));
   EXPECT_TRUE(LogContainsEvent(
       entries, 1, NetLog::TYPE_SOCKET_POOL_BOUND_TO_CONNECT_JOB,
       NetLog::PHASE_NONE));
@@ skipping 332 matching lines @@
                        LOWEST,
                        callback.callback(),
                        pool_.get(),
                        BoundNetLog());
   ASSERT_EQ(ERR_IO_PENDING, rv);
   EXPECT_EQ(LOAD_STATE_CONNECTING, pool_->GetLoadState("a", &handle));
   ASSERT_EQ(OK, callback.WaitForResult());
 
   // Use and release the socket.
   EXPECT_EQ(1, handle.socket()->Write(NULL, 1, CompletionCallback()));
+  TestLoadTimingInfoConnectedNotReused(handle);
   handle.Reset();
 
   // Should now have one idle socket.
   ASSERT_EQ(1, pool_->IdleSocketCount());
 
   // Request a new socket. This should reuse the old socket and complete
   // synchronously.
   CapturingBoundNetLog log;
   rv = handle.Init("a",
                    params_,
                    LOWEST,
                    CompletionCallback(),
                    pool_.get(),
                    log.bound());
   ASSERT_EQ(OK, rv);
   EXPECT_TRUE(handle.is_reused());
+  TestLoadTimingInfoConnectedReused(handle);
 
   ASSERT_TRUE(pool_->HasGroup("a"));
   EXPECT_EQ(0, pool_->IdleSocketCountInGroup("a"));
   EXPECT_EQ(1, pool_->NumActiveSocketsInGroup("a"));
 
   CapturingNetLog::CapturedEntryList entries;
   log.GetEntries(&entries);
   EXPECT_TRUE(LogContainsEntryWithType(
       entries, 1, NetLog::TYPE_SOCKET_POOL_REUSED_AN_EXISTING_SOCKET));
 }
@@ skipping 1303 matching lines @@
                                          callback1.callback(),
                                          pool_.get(),
                                          BoundNetLog()));
 
   EXPECT_EQ(1, pool_->NumConnectJobsInGroup("a"));
   EXPECT_EQ(0, pool_->NumUnassignedConnectJobsInGroup("a"));
   EXPECT_EQ(0, pool_->IdleSocketCountInGroup("a"));
 
   ASSERT_EQ(OK, callback1.WaitForResult());
 
+  // Make sure if a preconneced socket is not fully connected when a request
+  // starts, it has a connect start time.
+  TestLoadTimingInfoConnectedNotReused(handle1);
   handle1.Reset();
 
   EXPECT_EQ(1, pool_->IdleSocketCountInGroup("a"));
 }
 
+// Checks that fully connected preconnect jobs have no connect times, and are
+// marked as reused.
+TEST_F(ClientSocketPoolBaseTest, ConnectedPreconnectJobsHaveNoConnectTimes) {
+  CreatePool(kDefaultMaxSockets, kDefaultMaxSocketsPerGroup);
+  connect_job_factory_->set_job_type(TestConnectJob::kMockJob);
+  pool_->RequestSockets("a", &params_, 1, BoundNetLog());
+
+  ASSERT_TRUE(pool_->HasGroup("a"));
+  EXPECT_EQ(0, pool_->NumConnectJobsInGroup("a"));
+  EXPECT_EQ(0, pool_->NumUnassignedConnectJobsInGroup("a"));
+  EXPECT_EQ(1, pool_->IdleSocketCountInGroup("a"));
+
+  ClientSocketHandle handle;
+  TestCompletionCallback callback;
+  EXPECT_EQ(OK, handle.Init("a",
+                            params_,
+                            kDefaultPriority,
+                            callback.callback(),
+                            pool_.get(),
+                            BoundNetLog()));
+
+  // Make sure the idle socket was used.
+  EXPECT_EQ(0, pool_->IdleSocketCountInGroup("a"));
+
+  TestLoadTimingInfoConnectedReused(handle);
+  handle.Reset();
+  TestLoadTimingInfoNotConnected(handle);
+}
+
 // http://crbug.com/64940 regression test.
 TEST_F(ClientSocketPoolBaseTest, PreconnectClosesIdleSocketRemovesGroup) {
   const int kMaxTotalSockets = 3;
   const int kMaxSocketsPerGroup = 2;
   CreatePool(kMaxTotalSockets, kMaxSocketsPerGroup);
   connect_job_factory_->set_job_type(TestConnectJob::kMockPendingJob);
 
   // Note that group name ordering matters here.  "a" comes before "b", so
   // CloseOneIdleSocket() will try to close "a"'s idle socket.
 
@@ skipping 123 matching lines @@
   // complete.
   EXPECT_EQ(1, pool_->NumConnectJobsInGroup("a"));
   EXPECT_EQ(0, pool_->NumUnassignedConnectJobsInGroup("a"));
   EXPECT_EQ(0, pool_->IdleSocketCountInGroup("a"));
   EXPECT_EQ(1, pool_->NumActiveSocketsInGroup("a"));
 }
 
 }  // namespace
 
 }  // namespace net