Log server advertised protos and the selected

next_proto to net-internals log.

In net internal logs, we will log proto in the following
manner:

(P) t=1323112212350 [st=463]     
    HTTP_STREAM_REQUEST_PROTO             
        --> next_proto_status = "negotiated"
        --> proto = "spdy/2"                
        --> server_protos = "spdy/2,http/1.1"

BUG=62064
TEST=network unit tests
R=willchan

The following was the original CL:
http://codereview.chromium.org/8676046/
Review URL: http://codereview.chromium.org/8787011

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@113052 0039d316-1c4b-4281-b951-d872f2087c98

16 files changed, 139 insertions, 19 deletions

diff --git a/net/base/net_log_event_type_list.h b/net/base/net_log_event_type_list.h
index aa9d890..c6a8ff7 100644
--- a/net/base/net_log_event_type_list.h
+++ b/net/base/net_log_event_type_list.h
@@ -800,6 +800,14 @@ EVENT_TYPE(HTTP_STREAM_JOB)
 //   }
 EVENT_TYPE(HTTP_STREAM_REQUEST_BOUND_TO_JOB)
 
+// Logs the protocol negotiated with the server. The event parameters are:
+//   {
+//      "status": <The NPN status ("negotiated", "unsupported", "no-overlap")>,
+//      "proto": <The NPN protocol negotiated>,
+//      "server_protos": <The list of server advertised protocols>,
+//   }
+EVENT_TYPE(HTTP_STREAM_REQUEST_PROTO)
+
 // ------------------------------------------------------------------------
 // HttpNetworkTransaction
 // ------------------------------------------------------------------------
diff --git a/net/http/http_stream_factory_impl_job.cc b/net/http/http_stream_factory_impl_job.cc
index e1bffb374..02a93d2 100644
--- a/net/http/http_stream_factory_impl_job.cc
+++ b/net/http/http_stream_factory_impl_job.cc
@@ -65,6 +65,43 @@ Value* HttpStreamJobParameters::ToValue() const {
   return dict;
 }
 
+// Parameters associated with the Proto (with NPN negotiation) of a HTTP stream.
+class HttpStreamProtoParameters : public NetLog::EventParameters {
+ public:
+  static scoped_refptr<HttpStreamProtoParameters> Create(
+      const SSLClientSocket::NextProtoStatus status,
+      const std::string& proto,
+      const std::string& server_protos) {
+    return make_scoped_refptr(new HttpStreamProtoParameters(
+        status, proto, server_protos));
+  }
+
+  virtual Value* ToValue() const;
+
+ private:
+  HttpStreamProtoParameters(const SSLClientSocket::NextProtoStatus status,
+                            const std::string& proto,
+                            const std::string& server_protos)
+      : status_(status),
+        proto_(proto),
+        server_protos_(server_protos) {}
+
+  const SSLClientSocket::NextProtoStatus status_;
+  const std::string proto_;
+  const std::string server_protos_;
+};
+
+Value* HttpStreamProtoParameters::ToValue() const {
+  DictionaryValue* dict = new DictionaryValue();
+
+  dict->SetString("next_proto_status",
+                  SSLClientSocket::NextProtoStatusToString(status_));
+  dict->SetString("proto", proto_);
+  dict->SetString("server_protos",
+                  SSLClientSocket::ServerProtosToString(server_protos_));
+  return dict;
+}
+
 HttpStreamFactoryImpl::Job::Job(HttpStreamFactoryImpl* stream_factory,
                                 HttpNetworkSession* session,
                                 const HttpRequestInfo& request_info,
@@ -711,6 +748,13 @@ int HttpStreamFactoryImpl::Job::DoInitConnectionComplete(int result) {
       static_cast<SSLClientSocket*>(connection_->socket());
     if (ssl_socket->was_npn_negotiated()) {
       was_npn_negotiated_ = true;
+      std::string proto;
+      std::string server_protos;
+      SSLClientSocket::NextProtoStatus status =
+          ssl_socket->GetNextProto(&proto, &server_protos);
+      net_log_.AddEvent(
+           NetLog::TYPE_HTTP_STREAM_REQUEST_PROTO,
+           HttpStreamProtoParameters::Create(status, proto, server_protos));
       if (ssl_socket->was_spdy_negotiated())
         SwitchToSpdyMode();
     }
diff --git a/net/socket/socket_test_util.cc b/net/socket/socket_test_util.cc
index 2444756..9685697 100644
--- a/net/socket/socket_test_util.cc
+++ b/net/socket/socket_test_util.cc
@@ -692,8 +692,9 @@ int MockClientSocket::ExportKeyingMaterial(const base::StringPiece& label,
 }
 
 SSLClientSocket::NextProtoStatus
-MockClientSocket::GetNextProto(std::string* proto) {
+MockClientSocket::GetNextProto(std::string* proto, std::string* server_protos) {
   proto->clear();
+  server_protos->clear();
   return SSLClientSocket::kNextProtoUnsupported;
 }
 
@@ -1154,8 +1155,9 @@ void MockSSLClientSocket::GetSSLCertRequestInfo(
 }
 
 SSLClientSocket::NextProtoStatus MockSSLClientSocket::GetNextProto(
-    std::string* proto) {
+    std::string* proto, std::string* server_protos) {
   *proto = data_->next_proto;
+  *server_protos = data_->server_protos;
   return data_->next_proto_status;
 }
 
diff --git a/net/socket/socket_test_util.h b/net/socket/socket_test_util.h
index e1d2b2a..c7082ca 100644
--- a/net/socket/socket_test_util.h
+++ b/net/socket/socket_test_util.h
@@ -263,6 +263,7 @@ struct SSLSocketDataProvider {
   MockConnect connect;
   SSLClientSocket::NextProtoStatus next_proto_status;
   std::string next_proto;
+  std::string server_protos;
   bool was_npn_negotiated;
   bool client_cert_sent;
   net::SSLCertRequestInfo* cert_request_info;
@@ -610,7 +611,8 @@ class MockClientSocket : public net::SSLClientSocket {
                                    const base::StringPiece& context,
                                    unsigned char *out,
                                    unsigned int outlen) OVERRIDE;
-  virtual NextProtoStatus GetNextProto(std::string* proto) OVERRIDE;
+  virtual NextProtoStatus GetNextProto(std::string* proto,
+                                       std::string* server_protos) OVERRIDE;
 
  protected:
   virtual ~MockClientSocket();
@@ -752,7 +754,8 @@ class MockSSLClientSocket : public MockClientSocket, public AsyncSocket {
   virtual void GetSSLInfo(net::SSLInfo* ssl_info) OVERRIDE;
   virtual void GetSSLCertRequestInfo(
       net::SSLCertRequestInfo* cert_request_info) OVERRIDE;
-  virtual NextProtoStatus GetNextProto(std::string* proto) OVERRIDE;
+  virtual NextProtoStatus GetNextProto(std::string* proto,
+                                       std::string* server_protos) OVERRIDE;
   virtual bool was_npn_negotiated() const OVERRIDE;
   virtual bool set_was_npn_negotiated(bool negotiated) OVERRIDE;
 
diff --git a/net/socket/ssl_client_socket.cc b/net/socket/ssl_client_socket.cc
index 5635ad5..4f87202 100644
--- a/net/socket/ssl_client_socket.cc
+++ b/net/socket/ssl_client_socket.cc
@@ -1,9 +1,11 @@
-// Copyright (c) 2010 The Chromium Authors. All rights reserved.
+// Copyright (c) 2011 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/ssl_client_socket.h"
 
+#include "base/string_util.h"
+
 namespace net {
 
 SSLClientSocket::SSLClientSocket()
@@ -24,6 +26,35 @@ SSLClientSocket::NextProto SSLClientSocket::NextProtoFromString(
   }
 }
 
+// static
+const char* SSLClientSocket::NextProtoStatusToString(
+    const SSLClientSocket::NextProtoStatus status) {
+  switch (status) {
+    case kNextProtoUnsupported:
+      return "unsupported";
+    case kNextProtoNegotiated:
+      return "negotiated";
+    case kNextProtoNoOverlap:
+      return "no-overlap";
+  }
+  return NULL;
+}
+
+// static
+std::string SSLClientSocket::ServerProtosToString(
+    const std::string& server_protos) {
+  const char* protos = server_protos.c_str();
+  size_t protos_len = server_protos.length();
+  std::vector<std::string> server_protos_with_commas;
+  for (size_t i = 0; i < protos_len; ) {
+    const size_t len = protos[i];
+    std::string proto_str(&protos[i + 1], len);
+    server_protos_with_commas.push_back(proto_str);
+    i += len + 1;
+  }
+  return JoinString(server_protos_with_commas, ',');
+}
+
 bool SSLClientSocket::IgnoreCertError(int error, int load_flags) {
   if (error == OK || load_flags & LOAD_IGNORE_ALL_CERT_ERRORS)
     return true;
diff --git a/net/socket/ssl_client_socket.h b/net/socket/ssl_client_socket.h
index ca4393b..a496ed2 100644
--- a/net/socket/ssl_client_socket.h
+++ b/net/socket/ssl_client_socket.h
@@ -121,10 +121,19 @@ class NET_EXPORT SSLClientSocket : public SSLSocket {
   //   kNextProtoNegotiated:  *proto is set to the negotiated protocol.
   //   kNextProtoNoOverlap:   *proto is set to the first protocol in the
   //                          supported list.
-  virtual NextProtoStatus GetNextProto(std::string* proto) = 0;
+  // *server_protos is set to the server advertised protocols.
+  virtual NextProtoStatus GetNextProto(std::string* proto,
+                                       std::string* server_protos) = 0;
 
   static NextProto NextProtoFromString(const std::string& proto_string);
 
+  static const char* NextProtoStatusToString(
+      const SSLClientSocket::NextProtoStatus status);
+
+  // Can be used with the second argument(|server_protos|) of |GetNextProto| to
+  // construct a comma separated string of server advertised protocols.
+  static std::string ServerProtosToString(const std::string& server_protos);
+
   static bool IgnoreCertError(int error, int load_flags);
 
   virtual bool was_npn_negotiated() const;
diff --git a/net/socket/ssl_client_socket_mac.cc b/net/socket/ssl_client_socket_mac.cc
index 6f87260..c719946 100644
--- a/net/socket/ssl_client_socket_mac.cc
+++ b/net/socket/ssl_client_socket_mac.cc
@@ -792,8 +792,10 @@ int SSLClientSocketMac::ExportKeyingMaterial(const base::StringPiece& label,
 }
 
 SSLClientSocket::NextProtoStatus
-SSLClientSocketMac::GetNextProto(std::string* proto) {
+SSLClientSocketMac::GetNextProto(std::string* proto,
+                                 std::string* server_protos) {
   proto->clear();
+  server_protos->clear();
   return kNextProtoUnsupported;
 }
 
diff --git a/net/socket/ssl_client_socket_mac.h b/net/socket/ssl_client_socket_mac.h
index febf072..7fa95c4 100644
--- a/net/socket/ssl_client_socket_mac.h
+++ b/net/socket/ssl_client_socket_mac.h
@@ -48,7 +48,8 @@ class SSLClientSocketMac : public SSLClientSocket {
                                    const base::StringPiece& context,
                                    unsigned char *out,
                                    unsigned int outlen) OVERRIDE;
-  virtual NextProtoStatus GetNextProto(std::string* proto) OVERRIDE;
+  virtual NextProtoStatus GetNextProto(std::string* proto,
+                                       std::string* server_protos) OVERRIDE;
 
   // StreamSocket methods:
   virtual int Connect(OldCompletionCallback* callback) OVERRIDE;
diff --git a/net/socket/ssl_client_socket_nss.cc b/net/socket/ssl_client_socket_nss.cc
index 18c0cf7..16b8da2 100644
--- a/net/socket/ssl_client_socket_nss.cc
+++ b/net/socket/ssl_client_socket_nss.cc
@@ -558,8 +558,10 @@ int SSLClientSocketNSS::ExportKeyingMaterial(const base::StringPiece& label,
 }
 
 SSLClientSocket::NextProtoStatus
-SSLClientSocketNSS::GetNextProto(std::string* proto) {
+SSLClientSocketNSS::GetNextProto(std::string* proto,
+                                 std::string* server_protos) {
   *proto = next_proto_;
+  *server_protos = server_protos_;
   return next_proto_status_;
 }
 
@@ -2600,6 +2602,9 @@ SSLClientSocketNSS::NextProtoCallback(void* arg,
     i += len + 1;
   }
 
+  that->server_protos_.assign(
+      reinterpret_cast<const char*>(protos), protos_len);
+
   // If we didn't find a protocol, we select the first one from our list.
   if (that->next_proto_status_ != kNextProtoNegotiated) {
     that->next_proto_status_ = kNextProtoNoOverlap;
diff --git a/net/socket/ssl_client_socket_nss.h b/net/socket/ssl_client_socket_nss.h
index 1136e61..0eddd76 100644
--- a/net/socket/ssl_client_socket_nss.h
+++ b/net/socket/ssl_client_socket_nss.h
@@ -67,7 +67,8 @@ class SSLClientSocketNSS : public SSLClientSocket {
                                    const base::StringPiece& context,
                                    unsigned char *out,
                                    unsigned int outlen) OVERRIDE;
-  virtual NextProtoStatus GetNextProto(std::string* proto) OVERRIDE;
+  virtual NextProtoStatus GetNextProto(std::string* proto,
+                                       std::string* server_protos) OVERRIDE;
 
   // StreamSocket methods:
   virtual int Connect(OldCompletionCallback* callback) OVERRIDE;
@@ -300,6 +301,8 @@ class SSLClientSocketNSS : public SSLClientSocket {
   // next_proto_ is the protocol that we selected by NPN.
   std::string next_proto_;
   NextProtoStatus next_proto_status_;
+  // Server's NPN advertised protocols.
+  std::string server_protos_;
 
   // The following two variables are added for debugging bug 65948. Will
   // remove this code after fixing bug 65948.
diff --git a/net/socket/ssl_client_socket_openssl.cc b/net/socket/ssl_client_socket_openssl.cc
index 14b5790..e2f3a78 100644
--- a/net/socket/ssl_client_socket_openssl.cc
+++ b/net/socket/ssl_client_socket_openssl.cc
@@ -605,8 +605,9 @@ int SSLClientSocketOpenSSL::ExportKeyingMaterial(
 }
 
 SSLClientSocket::NextProtoStatus SSLClientSocketOpenSSL::GetNextProto(
-    std::string* proto) {
+    std::string* proto, std::string* server_protos) {
   *proto = npn_proto_;
+  *server_protos = server_protos_;
   return npn_status_;
 }
 
@@ -826,6 +827,7 @@ int SSLClientSocketOpenSSL::SelectNextProtoCallback(unsigned char** out,
   }
 
   npn_proto_.assign(reinterpret_cast<const char*>(*out), *outlen);
+  server_protos_.assign(reinterpret_cast<const char*>(in), inlen);
   switch (status) {
     case OPENSSL_NPN_NEGOTIATED:
       npn_status_ = SSLClientSocket::kNextProtoNegotiated;
diff --git a/net/socket/ssl_client_socket_openssl.h b/net/socket/ssl_client_socket_openssl.h
index a09fff4..281bb1c 100644
--- a/net/socket/ssl_client_socket_openssl.h
+++ b/net/socket/ssl_client_socket_openssl.h
@@ -59,7 +59,8 @@ class SSLClientSocketOpenSSL : public SSLClientSocket {
                                    const base::StringPiece& context,
                                    unsigned char *out,
                                    unsigned int outlen);
-  virtual NextProtoStatus GetNextProto(std::string* proto);
+  virtual NextProtoStatus GetNextProto(std::string* proto,
+                                       std::string* server_protos);
 
   // StreamSocket methods:
   virtual int Connect(OldCompletionCallback* callback);
@@ -163,6 +164,7 @@ class SSLClientSocketOpenSSL : public SSLClientSocket {
   State next_handshake_state_;
   NextProtoStatus npn_status_;
   std::string npn_proto_;
+  std::string server_protos_;
   BoundNetLog net_log_;
 };
 
diff --git a/net/socket/ssl_client_socket_pool.cc b/net/socket/ssl_client_socket_pool.cc
index a924b5a..4fffac6 100644
--- a/net/socket/ssl_client_socket_pool.cc
+++ b/net/socket/ssl_client_socket_pool.cc
@@ -286,11 +286,12 @@ int SSLConnectJob::DoSSLConnectComplete(int result) {
   SSLClientSocket::NextProtoStatus status =
       SSLClientSocket::kNextProtoUnsupported;
   std::string proto;
+  std::string server_protos;
   // GetNextProto will fail and and trigger a NOTREACHED if we pass in a socket
   // that hasn't had SSL_ImportFD called on it. If we get a certificate error
   // here, then we know that we called SSL_ImportFD.
   if (result == OK || IsCertificateError(result))
-    status = ssl_socket_->GetNextProto(&proto);
+    status = ssl_socket_->GetNextProto(&proto, &server_protos);
 
   // If we want spdy over npn, make sure it succeeded.
   if (status == SSLClientSocket::kNextProtoNegotiated) {
diff --git a/net/socket/ssl_client_socket_pool_unittest.cc b/net/socket/ssl_client_socket_pool_unittest.cc
index 7ade2e8..7da8aaa 100644
--- a/net/socket/ssl_client_socket_pool_unittest.cc
+++ b/net/socket/ssl_client_socket_pool_unittest.cc
@@ -382,7 +382,8 @@ TEST_F(SSLClientSocketPoolTest, DirectGotSPDY) {
   SSLClientSocket* ssl_socket = static_cast<SSLClientSocket*>(handle.socket());
   EXPECT_TRUE(ssl_socket->was_npn_negotiated());
   std::string proto;
-  ssl_socket->GetNextProto(&proto);
+  std::string server_protos;
+  ssl_socket->GetNextProto(&proto, &server_protos);
   EXPECT_EQ(SSLClientSocket::NextProtoFromString(proto),
             SSLClientSocket::kProtoSPDY2);
 }
@@ -414,7 +415,8 @@ TEST_F(SSLClientSocketPoolTest, DirectGotBonusSPDY) {
   SSLClientSocket* ssl_socket = static_cast<SSLClientSocket*>(handle.socket());
   EXPECT_TRUE(ssl_socket->was_npn_negotiated());
   std::string proto;
-  ssl_socket->GetNextProto(&proto);
+  std::string server_protos;
+  ssl_socket->GetNextProto(&proto, &server_protos);
   EXPECT_EQ(SSLClientSocket::NextProtoFromString(proto),
             SSLClientSocket::kProtoSPDY2);
 }
@@ -714,7 +716,8 @@ TEST_F(SSLClientSocketPoolTest, IPPooling) {
   SSLClientSocket* ssl_socket = static_cast<SSLClientSocket*>(handle->socket());
   EXPECT_TRUE(ssl_socket->was_npn_negotiated());
   std::string proto;
-  ssl_socket->GetNextProto(&proto);
+  std::string server_protos;
+  ssl_socket->GetNextProto(&proto, &server_protos);
   EXPECT_EQ(SSLClientSocket::NextProtoFromString(proto),
             SSLClientSocket::kProtoSPDY2);
 
@@ -801,7 +804,8 @@ TEST_F(SSLClientSocketPoolTest, IPPoolingClientCert) {
   SSLClientSocket* ssl_socket = static_cast<SSLClientSocket*>(handle->socket());
   EXPECT_TRUE(ssl_socket->was_npn_negotiated());
   std::string proto;
-  ssl_socket->GetNextProto(&proto);
+  std::string server_protos;
+  ssl_socket->GetNextProto(&proto, &server_protos);
   EXPECT_EQ(SSLClientSocket::NextProtoFromString(proto),
             SSLClientSocket::kProtoSPDY2);
 
diff --git a/net/socket/ssl_client_socket_win.cc b/net/socket/ssl_client_socket_win.cc
index 30441ce..1e42414 100644
--- a/net/socket/ssl_client_socket_win.cc
+++ b/net/socket/ssl_client_socket_win.cc
@@ -555,8 +555,10 @@ int SSLClientSocketWin::ExportKeyingMaterial(const base::StringPiece& label,
 }
 
 SSLClientSocket::NextProtoStatus
-SSLClientSocketWin::GetNextProto(std::string* proto) {
+SSLClientSocketWin::GetNextProto(std::string* proto,
+                                 std::string* server_protos) {
   proto->clear();
+  server_protos->clear();
   return kNextProtoUnsupported;
 }
 
diff --git a/net/socket/ssl_client_socket_win.h b/net/socket/ssl_client_socket_win.h
index d4cabf9..adff167 100644
--- a/net/socket/ssl_client_socket_win.h
+++ b/net/socket/ssl_client_socket_win.h
@@ -52,7 +52,8 @@ class SSLClientSocketWin : public SSLClientSocket {
                                    const base::StringPiece& context,
                                    unsigned char *out,
                                    unsigned int outlen);
-  virtual NextProtoStatus GetNextProto(std::string* proto);
+  virtual NextProtoStatus GetNextProto(std::string* proto,
+                                       std::string* server_protos);
 
   // StreamSocket methods:
   virtual int Connect(OldCompletionCallback* callback);