LoadTiming implementation in net, part 1.

net/socket/transport_client_socket_pool_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/transport_client_socket_pool.h"
 
 #include "base/bind.h"
 #include "base/bind_helpers.h"
 #include "base/callback.h"
 #include "base/compiler_specific.h"
 #include "base/logging.h"
 #include "base/message_loop.h"
 #include "base/threading/platform_thread.h"
+#include "net/base/capturing_net_log.h"
 #include "net/base/ip_endpoint.h"
+#include "net/base/load_timing_info.h"
 #include "net/base/mock_host_resolver.h"
 #include "net/base/net_errors.h"
 #include "net/base/net_util.h"
 #include "net/base/test_completion_callback.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/gtest/include/gtest/gtest.h"
 
 namespace net {
 
 using internal::ClientSocketPoolBaseHelper;
 
 namespace {
 
 const int kMaxSockets = 32;
 const int kMaxSocketsPerGroup = 6;
 const net::RequestPriority kDefaultPriority = LOW;
 
+// 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_TRUE(load_timing_info.socket_reused);
+  EXPECT_NE(NetLog::Source::kInvalidId, load_timing_info.socket_log_id);
+
+  EXPECT_TRUE(load_timing_info.connect_timing.connect_start.is_null());
+  EXPECT_TRUE(load_timing_info.connect_timing.connect_end.is_null());
+  EXPECT_TRUE(load_timing_info.connect_timing.dns_start.is_null());
+  EXPECT_TRUE(load_timing_info.connect_timing.dns_end.is_null());
+  EXPECT_TRUE(load_timing_info.connect_timing.ssl_start.is_null());
+  EXPECT_TRUE(load_timing_info.connect_timing.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_timing.dns_start.is_null());
+  EXPECT_LE(load_timing_info.connect_timing.dns_start,
+            load_timing_info.connect_timing.dns_end);
+  EXPECT_LE(load_timing_info.connect_timing.dns_end,
+            load_timing_info.connect_timing.connect_start);
+  EXPECT_LE(load_timing_info.connect_timing.connect_start,
+            load_timing_info.connect_timing.connect_end);
+
+  EXPECT_TRUE(load_timing_info.connect_timing.ssl_start.is_null());
+  EXPECT_TRUE(load_timing_info.connect_timing.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);
+}
+
 void SetIPv4Address(IPEndPoint* address) {
   IPAddressNumber number;
   CHECK(ParseIPLiteralToNumber("1.1.1.1", &number));
   *address = IPEndPoint(number, 80);
 }
 
 void SetIPv6Address(IPEndPoint* address) {
   IPAddressNumber number;
   CHECK(ParseIPLiteralToNumber("1:abcd::3:4:ff", &number));
   *address = IPEndPoint(number, 80);
 }
 
 class MockClientSocket : public StreamSocket {
  public:
-  MockClientSocket(const AddressList& addrlist)
+  MockClientSocket(const AddressList& addrlist, net::NetLog* net_log)
       : connected_(false),
-        addrlist_(addrlist) {}
+        addrlist_(addrlist),
+        net_log_(BoundNetLog::Make(net_log, NetLog::SOURCE_SOCKET)) {
+  }
 
   // StreamSocket implementation.
   virtual int Connect(const CompletionCallback& callback) {
     connected_ = true;
     return OK;
   }
   virtual void Disconnect() {
     connected_ = false;
   }
   virtual bool IsConnected() const {
@@ skipping 49 matching lines @@
   virtual bool SetSendBufferSize(int32 size) { return true; }
 
  private:
   bool connected_;
   const AddressList addrlist_;
   BoundNetLog net_log_;
 };
 
 class MockFailingClientSocket : public StreamSocket {
  public:
-  MockFailingClientSocket(const AddressList& addrlist) : addrlist_(addrlist) {}
+  MockFailingClientSocket(const AddressList& addrlist, net::NetLog* net_log)
+      : addrlist_(addrlist),
+        net_log_(BoundNetLog::Make(net_log, NetLog::SOURCE_SOCKET)) {
+  }
 
   // StreamSocket implementation.
   virtual int Connect(const CompletionCallback& callback) {
     return ERR_CONNECTION_FAILED;
   }
 
   virtual void Disconnect() {}
 
   virtual bool IsConnected() const {
     return false;
@@ skipping 50 matching lines @@
 class MockPendingClientSocket : public StreamSocket {
  public:
   // |should_connect| indicates whether the socket should successfully complete
   // or fail.
   // |should_stall| indicates that this socket should never connect.
   // |delay_ms| is the delay, in milliseconds, before simulating a connect.
   MockPendingClientSocket(
       const AddressList& addrlist,
       bool should_connect,
       bool should_stall,
-      base::TimeDelta delay)
+      base::TimeDelta delay,
+      net::NetLog* net_log)
       : ALLOW_THIS_IN_INITIALIZER_LIST(weak_factory_(this)),
         should_connect_(should_connect),
         should_stall_(should_stall),
         delay_(delay),
         is_connected_(false),
-        addrlist_(addrlist) {}
+        addrlist_(addrlist),
+        net_log_(BoundNetLog::Make(net_log, NetLog::SOURCE_SOCKET)) {
+  }
 
   // StreamSocket implementation.
   virtual int Connect(const CompletionCallback& callback) {
     MessageLoop::current()->PostDelayedTask(
         FROM_HERE,
         base::Bind(&MockPendingClientSocket::DoCallback,
                    weak_factory_.GetWeakPtr(), callback),
         delay_);
     return ERR_IO_PENDING;
   }
@@ skipping 82 matching lines @@
     MOCK_CLIENT_SOCKET,
     MOCK_FAILING_CLIENT_SOCKET,
     MOCK_PENDING_CLIENT_SOCKET,
     MOCK_PENDING_FAILING_CLIENT_SOCKET,
     // A delayed socket will pause before connecting through the message loop.
     MOCK_DELAYED_CLIENT_SOCKET,
     // A stalled socket that never connects at all.
     MOCK_STALLED_CLIENT_SOCKET,
   };
 
-  MockClientSocketFactory()
-      : allocation_count_(0), client_socket_type_(MOCK_CLIENT_SOCKET),
-        client_socket_types_(NULL), client_socket_index_(0),
-        client_socket_index_max_(0),
+  explicit MockClientSocketFactory(NetLog* net_log)
+      : net_log_(net_log), allocation_count_(0),
+        client_socket_type_(MOCK_CLIENT_SOCKET), client_socket_types_(NULL),
+        client_socket_index_(0), client_socket_index_max_(0),
         delay_(base::TimeDelta::FromMilliseconds(
             ClientSocketPool::kMaxConnectRetryIntervalMs)) {}
 
   virtual DatagramClientSocket* CreateDatagramClientSocket(
       DatagramSocket::BindType bind_type,
       const RandIntCallback& rand_int_cb,
       NetLog* net_log,
       const NetLog::Source& source) {
     NOTREACHED();
     return NULL;
   }
 
   virtual StreamSocket* CreateTransportClientSocket(
       const AddressList& addresses,
       NetLog* /* net_log */,
       const NetLog::Source& /* source */) {
     allocation_count_++;
 
     ClientSocketType type = client_socket_type_;
     if (client_socket_types_ &&
         client_socket_index_ < client_socket_index_max_) {
       type = client_socket_types_[client_socket_index_++];
     }
 
     switch (type) {
       case MOCK_CLIENT_SOCKET:
-        return new MockClientSocket(addresses);
+        return new MockClientSocket(addresses, net_log_);
       case MOCK_FAILING_CLIENT_SOCKET:
-        return new MockFailingClientSocket(addresses);
+        return new MockFailingClientSocket(addresses, net_log_);
       case MOCK_PENDING_CLIENT_SOCKET:
         return new MockPendingClientSocket(
-            addresses, true, false, base::TimeDelta());
+            addresses, true, false, base::TimeDelta(), net_log_);
       case MOCK_PENDING_FAILING_CLIENT_SOCKET:
         return new MockPendingClientSocket(
-            addresses, false, false, base::TimeDelta());
+            addresses, false, false, base::TimeDelta(), net_log_);
       case MOCK_DELAYED_CLIENT_SOCKET:
-        return new MockPendingClientSocket(addresses, true, false, delay_);
+        return new MockPendingClientSocket(
+            addresses, true, false, delay_, net_log_);
       case MOCK_STALLED_CLIENT_SOCKET:
         return new MockPendingClientSocket(
-            addresses, true, true, base::TimeDelta());
+            addresses, true, true, base::TimeDelta(), net_log_);
       default:
         NOTREACHED();
-        return new MockClientSocket(addresses);
+        return new MockClientSocket(addresses, net_log_);
     }
   }
 
   virtual SSLClientSocket* CreateSSLClientSocket(
       ClientSocketHandle* transport_socket,
       const HostPortPair& host_and_port,
       const SSLConfig& ssl_config,
       const SSLClientSocketContext& context) {
     NOTIMPLEMENTED();
     return NULL;
@@ skipping 14 matching lines @@
   void set_client_socket_types(ClientSocketType* type_list, int num_types) {
     DCHECK_GT(num_types, 0);
     client_socket_types_ = type_list;
     client_socket_index_ = 0;
     client_socket_index_max_ = num_types;
   }
 
   void set_delay(base::TimeDelta delay) { delay_ = delay; }
 
  private:
+  NetLog* net_log_;
   int allocation_count_;
   ClientSocketType client_socket_type_;
   ClientSocketType* client_socket_types_;
   int client_socket_index_;
   int client_socket_index_max_;
   base::TimeDelta delay_;
 };
 
 class TransportClientSocketPoolTest : public testing::Test {
  protected:
   TransportClientSocketPoolTest()
       : connect_backup_jobs_enabled_(
             ClientSocketPoolBaseHelper::set_connect_backup_jobs_enabled(true)),
         params_(
             new TransportSocketParams(HostPortPair("www.google.com", 80),
                                       kDefaultPriority, false, false,
                                       OnHostResolutionCallback())),
         low_params_(
             new TransportSocketParams(HostPortPair("www.google.com", 80),
                                       LOW, false, false,
                                       OnHostResolutionCallback())),
         histograms_(new ClientSocketPoolHistograms("TCPUnitTest")),
         host_resolver_(new MockHostResolver),
+        client_socket_factory_(&net_log_),
         pool_(kMaxSockets,
               kMaxSocketsPerGroup,
               histograms_.get(),
               host_resolver_.get(),
               &client_socket_factory_,
               NULL) {
   }
 
   ~TransportClientSocketPoolTest() {
     internal::ClientSocketPoolBaseHelper::set_connect_backup_jobs_enabled(
@@ skipping 17 matching lines @@
   }
 
   void ReleaseAllConnections(ClientSocketPoolTest::KeepAlive keep_alive) {
     test_base_.ReleaseAllConnections(keep_alive);
   }
 
   ScopedVector<TestSocketRequest>* requests() { return test_base_.requests(); }
   size_t completion_count() const { return test_base_.completion_count(); }
 
   bool connect_backup_jobs_enabled_;
+  CapturingNetLog net_log_;
   scoped_refptr<TransportSocketParams> params_;
   scoped_refptr<TransportSocketParams> low_params_;
   scoped_ptr<ClientSocketPoolHistograms> histograms_;
   scoped_ptr<MockHostResolver> host_resolver_;
   MockClientSocketFactory client_socket_factory_;
   TransportClientSocketPool pool_;
   ClientSocketPoolTest test_base_;
 };
 
 TEST(TransportConnectJobTest, MakeAddrListStartWithIPv4) {
@@ skipping 72 matching lines @@
   ClientSocketHandle handle;
   int rv = handle.Init("a", low_params_, LOW, callback.callback(), &pool_,
                        BoundNetLog());
   EXPECT_EQ(ERR_IO_PENDING, rv);
   EXPECT_FALSE(handle.is_initialized());
   EXPECT_FALSE(handle.socket());
 
   EXPECT_EQ(OK, callback.WaitForResult());
   EXPECT_TRUE(handle.is_initialized());
   EXPECT_TRUE(handle.socket());
-
-  handle.Reset();
+  TestLoadTimingInfoConnectedNotReused(handle);
 }
 
 TEST_F(TransportClientSocketPoolTest, InitHostResolutionFailure) {
   host_resolver_->rules()->AddSimulatedFailure("unresolvable.host.name");
   TestCompletionCallback callback;
   ClientSocketHandle handle;
   HostPortPair host_port_pair("unresolvable.host.name", 80);
   scoped_refptr<TransportSocketParams> dest(new TransportSocketParams(
       host_port_pair, kDefaultPriority, false, false,
       OnHostResolutionCallback()));
@@ skipping 345 matching lines @@
   ASSERT_LE(kNumRequests, kMaxSockets);  // Otherwise the test will hang.
 
   // Queue up all the requests
   for (int i = 0; i < kNumRequests; i++)
     EXPECT_EQ(ERR_IO_PENDING, StartRequest("a", kDefaultPriority));
 
   for (int i = 0; i < kNumRequests; i++)
     EXPECT_EQ(ERR_CONNECTION_FAILED, (*requests())[i]->WaitForResult());
 }
 
+TEST_F(TransportClientSocketPoolTest, IdleSocketLoadTiming) {
+  TestCompletionCallback callback;
+  ClientSocketHandle handle;
+  int rv = handle.Init("a", low_params_, LOW, callback.callback(), &pool_,
+                       BoundNetLog());
+  EXPECT_EQ(ERR_IO_PENDING, rv);
+  EXPECT_FALSE(handle.is_initialized());
+  EXPECT_FALSE(handle.socket());
+
+  EXPECT_EQ(OK, callback.WaitForResult());
+  EXPECT_TRUE(handle.is_initialized());
+  EXPECT_TRUE(handle.socket());
+  TestLoadTimingInfoConnectedNotReused(handle);
+
+  handle.Reset();
+  // Need to run all pending to release the socket back to the pool.
+  MessageLoop::current()->RunUntilIdle();
+
+  // Now we should have 1 idle socket.
+  EXPECT_EQ(1, pool_.IdleSocketCount());
+
+  rv = handle.Init("a", low_params_, LOW, callback.callback(), &pool_,
+                   BoundNetLog());
+  EXPECT_EQ(OK, rv);
+  EXPECT_EQ(0, pool_.IdleSocketCount());
+  TestLoadTimingInfoConnectedReused(handle);
+}
+
 TEST_F(TransportClientSocketPoolTest, ResetIdleSocketsOnIPAddressChange) {
   TestCompletionCallback callback;
   ClientSocketHandle handle;
   int rv = handle.Init("a", low_params_, LOW, callback.callback(), &pool_,
                        BoundNetLog());
   EXPECT_EQ(ERR_IO_PENDING, rv);
   EXPECT_FALSE(handle.is_initialized());
   EXPECT_FALSE(handle.socket());
 
   EXPECT_EQ(OK, callback.WaitForResult());
@@ skipping 362 matching lines @@
   EXPECT_TRUE(handle.socket());
   IPEndPoint endpoint;
   handle.socket()->GetLocalAddress(&endpoint);
   EXPECT_EQ(kIPv4AddressSize, endpoint.address().size());
   EXPECT_EQ(1, client_socket_factory_.allocation_count());
 }
 
 }  // namespace
 
 }  // namespace net