SSLClientSessionCache: Log number of times Lookup is called per Session.

net/socket/ssl_client_socket_impl.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/ssl_client_socket_impl.h"
 
 #include <errno.h>
 #include <string.h>
 
 #include <algorithm>
@@ skipping 1979 matching lines @@
       tb_was_negotiated_ = true;
       return 1;
     }
   }
 
   *out_alert_value = SSL_AD_ILLEGAL_PARAMETER;
   return 0;
 }
 
 void SSLClientSocketImpl::LogConnectEndEvent(int rv) {
+  SSLContext::GetInstance()->session_cache()->DecrementLookupCount(
+      GetSessionCacheKey(), negotiated_protocol_ == kProtoHTTP2);

[davidben, 2017/01/17 20:16:42]

Doing it in LogConnectEndEvent seems wrong. If Init() fails, you never did an
SSL_SESSION lookup. This gets called on failed connects too. I would think we
only need to do anything on successful connects (on failed connect, that would
still count as "using" the session since we've leaked it).

On successful connect, we would expect the TLS 1.3 server to mint us a new
ticket, so we should be able to reset the counter to zero, right?

[nharper, 2017/01/17 20:33:16]

The lookup happens in Init(), and it can return ERR_UNEXPECTED after that lookup
(all of the failures of Init() appear to be ERR_UNEXPECTED), so I need to
decrement the counter after Lookup.

How about adding a member to SSLClientSocketImpl bool log_session_lookup_ which
gets set to true after Lookup and false after DecrementLookupCount. I can also
add to the d'tor a check of that bool and a call to DecrementLookupCount in case
it's possible to start the connection and then destroy the socket before this
function gets called.

Other suggestions for where to put the DecrementLookupCount call to ensure it
gets called exactly once per Lookup are welcome.
We expect the server to mint a single ticket (although it could mint more), so
we decrement by one - the new ticket replaces the one we just used for this
connection.

[davidben, 2017/01/17 21:27:02]

Oh, I see. You're tracking active lookups. But if Init() fails after an active
lookup, we don't actually get a fresh session or anything, so if we're
simulating what would happen with single use tickets, that should simulate a
lookup we never get back.
Don't we mint two tickets? Though there was talk of whether we should just be
minting one. My thought was, just so we're only controlling one parameter at a
time, we'd act as if the server gave us an infinite number of tickets, record at
that point, and otherwise just increment the counter on lookup. Then we don't
need to hook too many things.

That would tell us how many times a session gets used in parallel before it is
used successfully.

   if (rv != OK) {
     net_log_.EndEventWithNetErrorCode(NetLogEventType::SSL_CONNECT, rv);
     return;
   }
 
   net_log_.EndEvent(NetLogEventType::SSL_CONNECT,
                     base::Bind(&NetLogSSLInfoCallback, base::Unretained(this)));
 }
 
 void SSLClientSocketImpl::RecordNegotiatedProtocol() const {
@@ skipping 55 matching lines @@
     if (ERR_GET_REASON(info->error_code) == SSL_R_TLSV1_ALERT_ACCESS_DENIED &&
         !certificate_requested_) {
       net_error = ERR_SSL_PROTOCOL_ERROR;
     }
   }
 
   return net_error;
 }
 
 }  // namespace net