net: Make Snap Start check cert verification and add metrics

This CL causes Snap Start to only trigger if the certificate
verification has completed by the time we are ready to send out the
handshake message.

It also adds a couple of NetLog entries and histograms around the Snap
Start code.

BUG=none
TEST=none

http://codereview.chromium.org/4408001

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

5 files changed, 60 insertions, 12 deletions

diff --git a/net/base/net_log_event_type_list.h b/net/base/net_log_event_type_list.h
index 398f7c1..6183749 100644
--- a/net/base/net_log_event_type_list.h
+++ b/net/base/net_log_event_type_list.h
@@ -334,6 +334,17 @@ EVENT_TYPE(SSL_HANDSHAKE_ERROR)
 EVENT_TYPE(SSL_READ_ERROR)
 EVENT_TYPE(SSL_WRITE_ERROR)
 
+// An SSL Snap Start was attempted
+// The following parameters are attached to the event:
+//   {
+//     "type": <Integer code for the Snap Start result>,
+//   }
+EVENT_TYPE(SSL_SNAP_START)
+
+// We found that our prediction of the server's certificates was correct and
+// we merged the verification with the SSLHostInfo.
+EVENT_TYPE(SSL_VERIFICATION_MERGED)
+
 // An SSL error occurred while calling an NSS function not directly related to
 // one of the above activities.  Can also be used when more information than
 // is provided by just an error code is needed:
diff --git a/net/socket/ssl_client_socket_nss.cc b/net/socket/ssl_client_socket_nss.cc
index 2512731..df2ac6a 100644
--- a/net/socket/ssl_client_socket_nss.cc
+++ b/net/socket/ssl_client_socket_nss.cc
@@ -480,6 +480,8 @@ void SSLClientSocketNSS::SaveSnapStartInfo() {
     NOTREACHED();
     return;
   }
+  net_log_.AddEvent(NetLog::TYPE_SSL_SNAP_START,
+                    new NetLogIntegerParameter("type", snap_start_type));
   LOG(ERROR) << "Snap Start: " << snap_start_type << " " << hostname_;
   if (snap_start_type == SSL_SNAP_START_FULL ||
       snap_start_type == SSL_SNAP_START_RESUME) {
@@ -743,7 +745,7 @@ int SSLClientSocketNSS::InitializeSSLOptions() {
   // TODO(agl): check that SSL_ENABLE_SNAP_START actually does something in the
   // current NSS code.
   rv = SSL_OptionSet(nss_fd_, SSL_ENABLE_SNAP_START,
-                     SSLConfigService::snap_start_enabled());
+                     ssl_config_.snap_start_enabled);
   if (rv != SECSuccess)
     VLOG(1) << "SSL_ENABLE_SNAP_START failed.  Old system nss?";
 #endif
@@ -1849,15 +1851,26 @@ void SSLClientSocketNSS::HandshakeCallback(PRFileDesc* socket,
 int SSLClientSocketNSS::DoSnapStartLoadInfo() {
   EnterFunction("");
   int rv = ssl_host_info_->WaitForDataReady(&handshake_io_callback_);
+  GotoState(STATE_HANDSHAKE);
 
   if (rv == OK) {
-    if (LoadSnapStartInfo()) {
-      pseudo_connected_ = true;
-      GotoState(STATE_SNAP_START_WAIT_FOR_WRITE);
-      if (user_connect_callback_)
-        DoConnectCallback(OK);
-    } else {
-      GotoState(STATE_HANDSHAKE);
+    if (ssl_host_info_->WaitForCertVerification(NULL) == OK) {
+      if (LoadSnapStartInfo()) {
+        pseudo_connected_ = true;
+        GotoState(STATE_SNAP_START_WAIT_FOR_WRITE);
+        if (user_connect_callback_)
+          DoConnectCallback(OK);
+      }
+    } else if (!ssl_host_info_->state().server_hello.empty()) {
+      // A non-empty ServerHello suggests that we would have tried a Snap Start
+      // connection.
+      base::TimeTicks now = base::TimeTicks::Now();
+      const base::TimeDelta duration =
+          now - ssl_host_info_->verification_start_time();
+      UMA_HISTOGRAM_TIMES("Net.SSLSnapStartNeededVerificationInMs", duration);
+      VLOG(1) << "Cannot snap start because verification isn't ready. "
+              << "Wanted verification after "
+              << duration.InMilliseconds() << "ms";
     }
   } else {
     DCHECK_EQ(ERR_IO_PENDING, rv);
@@ -2224,8 +2237,15 @@ int SSLClientSocketNSS::DoVerifyCert(int result) {
     // server then it will have optimistically started a verification of that
     // chain. So, if the prediction was correct, we should wait for that
     // verification to finish rather than start our own.
+    net_log_.AddEvent(NetLog::TYPE_SSL_VERIFICATION_MERGED, NULL);
+    UMA_HISTOGRAM_ENUMERATION("Net.SSLVerificationMerged", 1 /* true */, 2);
+    base::TimeTicks now = base::TimeTicks::Now();
+    UMA_HISTOGRAM_TIMES("Net.SSLVerificationMergedMsSaved",
+                        now - ssl_host_info_->verification_start_time());
     server_cert_verify_result_ = &ssl_host_info_->cert_verify_result();
     return ssl_host_info_->WaitForCertVerification(&handshake_io_callback_);
+  } else {
+    UMA_HISTOGRAM_ENUMERATION("Net.SSLVerificationMerged", 0 /* false */, 2);
   }
 
   int flags = 0;
@@ -2245,10 +2265,6 @@ int SSLClientSocketNSS::DoVerifyCert(int result) {
 int SSLClientSocketNSS::DoVerifyCertComplete(int result) {
   verifier_.reset();
 
-  // Using Snap Start disables certificate verification for now.
-  if (SSLConfigService::snap_start_enabled())
-    result = OK;
-
   // We used to remember the intermediate CA certs in the NSS database
   // persistently.  However, NSS opens a connection to the SQLite database
   // during NSS initialization and doesn't close the connection until NSS
@@ -2306,6 +2322,12 @@ int SSLClientSocketNSS::DoVerifyCertComplete(int result) {
     }
   }
 
+  if (user_read_callback_) {
+    int rv = DoReadLoop(OK);
+    if (rv != ERR_IO_PENDING)
+      DoReadCallback(rv);
+  }
+
   // Exit DoHandshakeLoop and return the result to the caller to Connect.
   DCHECK(next_handshake_state_ == STATE_NONE);
   return result;
diff --git a/net/socket/ssl_host_info.cc b/net/socket/ssl_host_info.cc
index ce042de..b44a963 100644
--- a/net/socket/ssl_host_info.cc
+++ b/net/socket/ssl_host_info.cc
@@ -4,6 +4,7 @@
 
 #include "net/socket/ssl_host_info.h"
 
+#include "base/metrics/histogram.h"
 #include "base/string_piece.h"
 #include "net/base/cert_verifier.h"
 #include "net/base/ssl_config_service.h"
@@ -110,6 +111,7 @@ bool SSLHostInfo::Parse(const std::string& data) {
         flags |= X509Certificate::VERIFY_REV_CHECKING_ENABLED;
       verifier_.reset(new CertVerifier);
       VLOG(1) << "Kicking off verification for " << hostname_;
+      verification_start_time_ = base::TimeTicks::Now();
       if (verifier_->Verify(cert_.get(), hostname_, flags,
                             &cert_verify_result_, callback_) == OK) {
         VerifyCallback(OK);
@@ -156,6 +158,11 @@ int SSLHostInfo::WaitForCertVerification(CompletionCallback* callback) {
 }
 
 void SSLHostInfo::VerifyCallback(int rv) {
+  DCHECK(!verification_start_time_.is_null());
+  base::TimeTicks now = base::TimeTicks::Now();
+  const base::TimeDelta duration = now - verification_start_time();
+  UMA_HISTOGRAM_TIMES("Net.SSLHostInfoVerificationTimeMs", duration);
+  VLOG(1) << "Verification took " << duration.InMilliseconds() << "ms";
   cert_verification_complete_ = true;
   cert_verification_result_ = rv;
   if (cert_verification_callback_) {
diff --git a/net/socket/ssl_host_info.h b/net/socket/ssl_host_info.h
index f919281..5f515fb 100644
--- a/net/socket/ssl_host_info.h
+++ b/net/socket/ssl_host_info.h
@@ -10,6 +10,7 @@
 
 #include "base/ref_counted.h"
 #include "base/scoped_ptr.h"
+#include "base/time.h"
 #include "net/base/cert_verify_result.h"
 #include "net/base/completion_callback.h"
 #include "net/socket/ssl_client_socket.h"
@@ -89,6 +90,10 @@ class SSLHostInfo {
   // verification.
   int WaitForCertVerification(CompletionCallback* callback);
 
+  base::TimeTicks verification_start_time() const {
+    return verification_start_time_;
+  }
+
  protected:
   // Parse parses an opaque blob of data and fills out the public member fields
   // of this object. It returns true iff the parse was successful. The public
@@ -110,6 +115,7 @@ class SSLHostInfo {
   // These two members are taken from the SSLConfig.
   bool rev_checking_enabled_;
   bool verify_ev_cert_;
+  base::TimeTicks verification_start_time_;
   CertVerifyResult cert_verify_result_;
   scoped_ptr<CertVerifier> verifier_;
   scoped_refptr<X509Certificate> cert_;
diff --git a/net/third_party/nss/ssl/snapstart.c b/net/third_party/nss/ssl/snapstart.c
index a2ad7f3..92406a7 100644
--- a/net/third_party/nss/ssl/snapstart.c
+++ b/net/third_party/nss/ssl/snapstart.c
@@ -1053,6 +1053,8 @@ ssl3_ResetForSnapStartRecovery(sslSocket *ss, SSL3Opaque *b, PRUint32 length)
         ss->ssl3.hs.snapStartType = snap_start_resume_recovery;
     }
 
+    ss->ssl3.nextProtoState = SSL_NEXT_PROTO_NO_SUPPORT;
+
     ssl3_DestroyCipherSpec(ss->ssl3.pwSpec, PR_TRUE/*freeSrvName*/);
 
     return SECSuccess;