LoadTiming implementation in net, part 1.

net/socket/ssl_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/http/http_proxy_client_socket_pool.h"
 
 #include "base/callback.h"
 #include "base/compiler_specific.h"
 #include "base/string_util.h"
 #include "base/time.h"
 #include "base/utf_string_conversions.h"
 #include "net/base/auth.h"
 #include "net/base/cert_verifier.h"
+#include "net/base/load_timing_info.h"
 #include "net/base/mock_host_resolver.h"
 #include "net/base/net_errors.h"
 #include "net/base/ssl_config_service_defaults.h"
 #include "net/base/test_certificate_data.h"
 #include "net/base/test_completion_callback.h"
 #include "net/http/http_auth_handler_factory.h"
 #include "net/http/http_network_session.h"
 #include "net/http/http_request_headers.h"
 #include "net/http/http_response_headers.h"
 #include "net/http/http_server_properties_impl.h"
 #include "net/proxy/proxy_service.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/spdy/spdy_session.h"
 #include "net/spdy/spdy_session_pool.h"
 #include "net/spdy/spdy_test_util_spdy2.h"
 #include "testing/gtest/include/gtest/gtest.h"
 
 using namespace net::test_spdy2;
 
 namespace net {
 
 namespace {
 
 const int kMaxSockets = 32;
 const int kMaxSocketsPerGroup = 6;
 
+// Make sure |handle|'s load times are set correctly.  DNS and connect start
+// times comes from mock client sockets in these tests, so primarily serves to
+// check those times were copied, and ssl times / connect end are set correctly.
+void TestLoadTimingInfo(const ClientSocketHandle& handle) {
+  LoadTimingInfo load_timing_info;
+  EXPECT_TRUE(handle.GetLoadTimingInfo(false, &load_timing_info));
+
+  EXPECT_FALSE(load_timing_info.socket_reused);
+  // None of these tests use a NetLog.
+  EXPECT_EQ(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.ssl_start);
+  EXPECT_LE(load_timing_info.connect_timing.ssl_start,
+            load_timing_info.connect_timing.ssl_end);
+  EXPECT_LE(load_timing_info.connect_timing.ssl_end,
+            load_timing_info.connect_timing.connect_end);
+
+  // None of these should be set by the socket handle.
+  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());
+}
+
+// Just like TestLoadTimingInfo, except DNS times are expected to be null, for
+// tests over proxies that do DNS lookups themselves.
+void TestLoadTimingInfoNoDns(const ClientSocketHandle& handle) {
+  LoadTimingInfo load_timing_info;
+  EXPECT_TRUE(handle.GetLoadTimingInfo(false, &load_timing_info));
+
+  // None of these tests use a NetLog.
+  EXPECT_EQ(NetLog::Source::kInvalidId, load_timing_info.socket_log_id);
+
+  EXPECT_FALSE(load_timing_info.socket_reused);
+
+  EXPECT_TRUE(load_timing_info.connect_timing.dns_start.is_null());
+  EXPECT_TRUE(load_timing_info.connect_timing.dns_end.is_null());
+  EXPECT_FALSE(load_timing_info.connect_timing.connect_start.is_null());
+  EXPECT_LE(load_timing_info.connect_timing.connect_start,
+            load_timing_info.connect_timing.ssl_start);
+  EXPECT_LE(load_timing_info.connect_timing.ssl_start,
+            load_timing_info.connect_timing.ssl_end);
+  EXPECT_LE(load_timing_info.connect_timing.ssl_end,
+            load_timing_info.connect_timing.connect_end);
+
+  // None of these should be set by the socket handle.
+  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 SSLClientSocketPoolTest : public testing::Test {
  protected:
   SSLClientSocketPoolTest()
       : proxy_service_(ProxyService::CreateDirect()),
         ssl_config_service_(new SSLConfigServiceDefaults),
         http_auth_handler_factory_(HttpAuthHandlerFactory::CreateDefault(
             &host_resolver_)),
         session_(CreateNetworkSession()),
         direct_transport_socket_params_(new TransportSocketParams(
             HostPortPair("host", 443), MEDIUM, false, false,
@@ skipping 177 matching lines @@
   scoped_refptr<SSLSocketParams> params = SSLParams(ProxyServer::SCHEME_DIRECT,
                                                     false);
 
   ClientSocketHandle handle;
   TestCompletionCallback callback;
   int rv = handle.Init(
       "a", params, MEDIUM, callback.callback(), pool_.get(), BoundNetLog());
   EXPECT_EQ(OK, rv);
   EXPECT_TRUE(handle.is_initialized());
   EXPECT_TRUE(handle.socket());
+  TestLoadTimingInfo(handle);
 }
 
 TEST_F(SSLClientSocketPoolTest, BasicDirectAsync) {
   StaticSocketDataProvider data;
   socket_factory_.AddSocketDataProvider(&data);
   SSLSocketDataProvider ssl(ASYNC, OK);
   socket_factory_.AddSSLSocketDataProvider(&ssl);
 
   CreatePool(true /* tcp pool */, false, false);
   scoped_refptr<SSLSocketParams> params = SSLParams(ProxyServer::SCHEME_DIRECT,
                                                     false);
 
   ClientSocketHandle handle;
   TestCompletionCallback callback;
   int rv = handle.Init(
       "a", params, MEDIUM, callback.callback(), pool_.get(), 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());
+  TestLoadTimingInfo(handle);
 }
 
 TEST_F(SSLClientSocketPoolTest, DirectCertError) {
   StaticSocketDataProvider data;
   socket_factory_.AddSocketDataProvider(&data);
   SSLSocketDataProvider ssl(ASYNC, ERR_CERT_COMMON_NAME_INVALID);
   socket_factory_.AddSSLSocketDataProvider(&ssl);
 
   CreatePool(true /* tcp pool */, false, false);
   scoped_refptr<SSLSocketParams> params = SSLParams(ProxyServer::SCHEME_DIRECT,
                                                     false);
 
   ClientSocketHandle handle;
   TestCompletionCallback callback;
   int rv = handle.Init(
       "a", params, MEDIUM, callback.callback(), pool_.get(), BoundNetLog());
   EXPECT_EQ(ERR_IO_PENDING, rv);
   EXPECT_FALSE(handle.is_initialized());
   EXPECT_FALSE(handle.socket());
 
   EXPECT_EQ(ERR_CERT_COMMON_NAME_INVALID, callback.WaitForResult());
   EXPECT_TRUE(handle.is_initialized());
   EXPECT_TRUE(handle.socket());
+  TestLoadTimingInfo(handle);
 }
 
 TEST_F(SSLClientSocketPoolTest, DirectSSLError) {
   StaticSocketDataProvider data;
   socket_factory_.AddSocketDataProvider(&data);
   SSLSocketDataProvider ssl(ASYNC, ERR_SSL_PROTOCOL_ERROR);
   socket_factory_.AddSSLSocketDataProvider(&ssl);
 
   CreatePool(true /* tcp pool */, false, false);
   scoped_refptr<SSLSocketParams> params = SSLParams(ProxyServer::SCHEME_DIRECT,
@@ skipping 28 matching lines @@
   TestCompletionCallback callback;
   int rv = handle.Init(
       "a", params, MEDIUM, callback.callback(), pool_.get(), 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());
+  TestLoadTimingInfo(handle);
   SSLClientSocket* ssl_socket = static_cast<SSLClientSocket*>(handle.socket());
   EXPECT_TRUE(ssl_socket->WasNpnNegotiated());
 }
 
 TEST_F(SSLClientSocketPoolTest, DirectNoSPDY) {
   StaticSocketDataProvider data;
   socket_factory_.AddSocketDataProvider(&data);
   SSLSocketDataProvider ssl(ASYNC, OK);
   ssl.SetNextProto(kProtoHTTP11);
   socket_factory_.AddSSLSocketDataProvider(&ssl);
@@ skipping 31 matching lines @@
   TestCompletionCallback callback;
   int rv = handle.Init(
       "a", params, MEDIUM, callback.callback(), pool_.get(), 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());
+  TestLoadTimingInfo(handle);
 
   SSLClientSocket* ssl_socket = static_cast<SSLClientSocket*>(handle.socket());
   EXPECT_TRUE(ssl_socket->WasNpnNegotiated());
   std::string proto;
   std::string server_protos;
   ssl_socket->GetNextProto(&proto, &server_protos);
   EXPECT_EQ(SSLClientSocket::NextProtoFromString(proto),
             kProtoSPDY2);
 }
 
@@ skipping 12 matching lines @@
   TestCompletionCallback callback;
   int rv = handle.Init(
       "a", params, MEDIUM, callback.callback(), pool_.get(), 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());
+  TestLoadTimingInfo(handle);
 
   SSLClientSocket* ssl_socket = static_cast<SSLClientSocket*>(handle.socket());
   EXPECT_TRUE(ssl_socket->WasNpnNegotiated());
   std::string proto;
   std::string server_protos;
   ssl_socket->GetNextProto(&proto, &server_protos);
   EXPECT_EQ(SSLClientSocket::NextProtoFromString(proto),
             kProtoSPDY2);
 }
 
@@ skipping 50 matching lines @@
   scoped_refptr<SSLSocketParams> params = SSLParams(ProxyServer::SCHEME_SOCKS5,
                                                     false);
 
   ClientSocketHandle handle;
   TestCompletionCallback callback;
   int rv = handle.Init(
       "a", params, MEDIUM, callback.callback(), pool_.get(), BoundNetLog());
   EXPECT_EQ(OK, rv);
   EXPECT_TRUE(handle.is_initialized());
   EXPECT_TRUE(handle.socket());
+  // SOCKS5 generally has no DNS times, but the mock SOCKS5 sockets used here
+  // don't go through the real logic, unlike in the HTTP proxy tests.
+  TestLoadTimingInfo(handle);
 }
 
 TEST_F(SSLClientSocketPoolTest, SOCKSBasicAsync) {
   StaticSocketDataProvider data;
   socket_factory_.AddSocketDataProvider(&data);
   SSLSocketDataProvider ssl(ASYNC, OK);
   socket_factory_.AddSSLSocketDataProvider(&ssl);
 
   CreatePool(false, true /* http proxy pool */, true /* socks pool */);
   scoped_refptr<SSLSocketParams> params = SSLParams(ProxyServer::SCHEME_SOCKS5,
                                                     false);
 
   ClientSocketHandle handle;
   TestCompletionCallback callback;
   int rv = handle.Init(
       "a", params, MEDIUM, callback.callback(), pool_.get(), 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());
+  // SOCKS5 generally has no DNS times, but the mock SOCKS5 sockets used here
+  // don't go through the real logic, unlike in the HTTP proxy tests.
+  TestLoadTimingInfo(handle);
 }
 
 TEST_F(SSLClientSocketPoolTest, HttpProxyFail) {
   StaticSocketDataProvider data;
   data.set_connect_data(MockConnect(SYNCHRONOUS, ERR_CONNECTION_FAILED));
   socket_factory_.AddSocketDataProvider(&data);
 
   CreatePool(false, true /* http proxy pool */, true /* socks pool */);
   scoped_refptr<SSLSocketParams> params = SSLParams(ProxyServer::SCHEME_HTTP,
                                                     false);
@@ skipping 54 matching lines @@
   scoped_refptr<SSLSocketParams> params = SSLParams(ProxyServer::SCHEME_HTTP,
                                                     false);
 
   ClientSocketHandle handle;
   TestCompletionCallback callback;
   int rv = handle.Init(
       "a", params, MEDIUM, callback.callback(), pool_.get(), BoundNetLog());
   EXPECT_EQ(OK, rv);
   EXPECT_TRUE(handle.is_initialized());
   EXPECT_TRUE(handle.socket());
+  TestLoadTimingInfoNoDns(handle);
 }
 
 TEST_F(SSLClientSocketPoolTest, HttpProxyBasicAsync) {
   MockWrite writes[] = {
       MockWrite("CONNECT host:80 HTTP/1.1\r\n"
                 "Host: host\r\n"
                 "Proxy-Connection: keep-alive\r\n"
                 "Proxy-Authorization: Basic Zm9vOmJhcg==\r\n\r\n"),
   };
   MockRead reads[] = {
@@ skipping 14 matching lines @@
   TestCompletionCallback callback;
   int rv = handle.Init(
       "a", params, MEDIUM, callback.callback(), pool_.get(), 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());
+  TestLoadTimingInfoNoDns(handle);
 }
 
 TEST_F(SSLClientSocketPoolTest, NeedProxyAuth) {
   MockWrite writes[] = {
       MockWrite("CONNECT host:80 HTTP/1.1\r\n"
                 "Host: host\r\n"
                 "Proxy-Connection: keep-alive\r\n\r\n"),
   };
   MockRead reads[] = {
       MockRead("HTTP/1.1 407 Proxy Authentication Required\r\n"),
@@ skipping 208 matching lines @@
   ssl.channel_id_sent = true;
   ssl.SetNextProto(kProtoSPDY2);
   TestIPPoolingDisabled(&ssl);
 }
 
 // It would be nice to also test the timeouts in SSLClientSocketPool.
 
 }  // namespace
 
 }  // namespace net