807435 - Telemetry for SSL Handshake time, version, and npn support

Status: RESOLVED FIXED

(Core :: Security: PSM, defect)

Description

[Patrick McManus [:mcmanus]]

Lots of talk of work on SSL performance recently, which is great. Hopefully we can get some telemetry to help guide/verify that.

This is a start.

In three patches:

* determine the SSL/TLS version distribution. There has been some concern over whether we are falling back to less than TLS too often, this should give some data as well as set the bound for where how often TLS-centric optimizations can apply.

* collect whether or not the NPN extension was used, and if used whether it found a match for a protocol we offer. Chrome bases false start off of this signal and it would be good to know the universe size and whether it is growing.

* a histogram of SSL connection times. A basic metric to see if other changes are moving the bottom line needle.

Comment 1

[Patrick McManus [:mcmanus]]

Attachment: patch 0 version rev 0

Comment 2

[Patrick McManus [:mcmanus]]

Attachment: patch 1 npn rev 0

Comment 3

[Patrick McManus [:mcmanus]]

Attachment: patch 2 timing rev 0

Comment 4

[Devdatta Akhawe [:devd]]

Just curious, why the n_values == 16 in the first patch?

Comment 5

[Patrick McManus [:mcmanus]]

(In reply to Devdatta Akhawe [:devd] from comment #4)
> Just curious, why the n_values == 16 in the first patch?

its meant to make sure that if we add new enumerations we can continue to use the same telemetry identifier.. or so I basically understand it from previous review comments.

Comment 6

[Patrick McManus [:mcmanus]]

Attachment: patch 3 ocsp rev 0

Add a fourth patch - this one measures OCSP success/fail rates along with their elapsed times. We can use this to confirm the size of the OCSP problem along with evaluating the impact of changes to the HTTP method that may (or may not) be made.

Technically this isn't just OCSP, but it will fit the bill for a telemetry number.

Comment 7

[Patrick McManus [:mcmanus]]

Attachment: patch 4 key exchange telemetry rev 0

This is the last patch I forsee adding to this particular series.

It records the key exchange algorithm used to complete an SSL handshake.

Google has attached false start to algorithms that maintain forward secrecy, this bit of telemetry should let us know how often that intersects with our handshakes and if it changes over time.

Comment 8

[Josh Aas]

I've asked Honza to do these reviews instead of Brian. Let us know if there is some reason Brian needs to do them instead of Honza.

Comment 9

[Honza Bambas (:mayhemer)]

Comment on attachment 681138 [details] [diff] [review]
patch 4 key exchange telemetry rev 0

Adding me as a secondary reviewer to all the patches, since these are PSM changes and those need reviews of two PSM peers when not created by a PSM peer.

Comment 10

[Brian Smith (:briansmith, :bsmith, use NEEDINFO?)]

Comment on attachment 677126 [details] [diff] [review]
patch 0 version rev 0

Review of attachment 677126 [details] [diff] [review]:
-----------------------------------------------------------------

r+ with comments addressed.

::: security/manager/ssl/src/nsNSSCallbacks.cpp
@@ +939,5 @@
> +    if (SSL_GetChannelInfo(fd, &channelInfo, sizeof(channelInfo)) == SECSuccess) {
> +      // Get the protocol version for telemetry
> +      // 0=unknown, 1=ssl2, 2=ssl3, 3=tls1.0, 4=tls1.1
> +
> +      unsigned int versionEnum = 0;

just use versionEnum = channelInfo.protocolVersion & 0xFF; This will always work because we the SSL_LIBRARY_VERSION_* values are always the on-the-wire version IDs, and we don't support SSL 2.0 anymore.

This would make 0=ssl3, 1=tls1, 2=tls1.1, 3=tls1.2. Make sure you update the comment above...

::: toolkit/components/telemetry/Histograms.json
@@ +708,5 @@
>    },
> +  "SSL_HANDSHAKE_VERSION": {
> +    "kind": "enumerated",
> +    "n_values": 16,
> +    "description": "SSL Version (0=unknown, 1=ssl2, 2=ssl3, 3=tls1.0, 4=tls1.1)"

...and here.

Comment 11

[Brian Smith (:briansmith, :bsmith, use NEEDINFO?)]

Comment on attachment 677127 [details] [diff] [review]
patch 1 npn rev 0

Review of attachment 677127 [details] [diff] [review]:
-----------------------------------------------------------------

r+ with review comments addressed.

::: security/manager/ssl/src/nsNSSCallbacks.cpp
@@ +930,5 @@
> +    if (SSL_GetNextProto(fd, &state, npnbuf, &npnlen, 256) == SECSuccess) {
> +      if (state == SSL_NEXT_PROTO_NEGOTIATED)
> +        infoObject->SetNegotiatedNPN(reinterpret_cast<char *>(npnbuf), npnlen);
> +      else
> +        infoObject->SetNegotiatedNPN(nullptr, 0);

It seems like the else is not needed and should be removed.

@@ +933,5 @@
> +      else
> +        infoObject->SetNegotiatedNPN(nullptr, 0);
> +
> +      // If these values change in ssl.h then telemetry will need to provide a
> +      // map. Right now we can use them directly

You can remove this comment. These values are not going to change because of the ABI compatibility that NSS provides.

Comment 12

[Brian Smith (:briansmith, :bsmith, use NEEDINFO?)]

Comment on attachment 677128 [details] [diff] [review]
patch 2 timing rev 0

Review of attachment 677128 [details] [diff] [review]:
-----------------------------------------------------------------

I will review the updated version again.

::: security/manager/ssl/src/nsNSSIOLayer.cpp
@@ +24,5 @@
>  #include "nsIInterfaceRequestorUtils.h"
>  #include "nsCharSeparatedTokenizer.h"
>  #include "nsIConsoleService.h"
>  #include "PSMRunnable.h"
> +#include "mozilla/Telemetry.h"

In PSM (at least), please put "mozilla/" includes above "ns" includes, in alphabetical order:

#include "<basename-of-cpp>.h" // always first

#include "mozilla/A.h"
#include "mozilla/B.h"
#include "nsA.h"
#include "nsB.h"

@@ +79,5 @@
>      mHandshakeCompleted(false),
>      mJoined(false),
>      mSentClientCert(false)
>  {
> +  mHandshakeTimestamp = TimeStamp::Now();

initialize in initializer list.

@@ +179,5 @@
>  void
> +nsNSSSocketInfo::SetHandshakeCompleted()
> +{
> +  mHandshakeCompleted = true;
> +  if (!mHandshakeTimestamp.IsNull()) {

I understand that you are trying to filter out renegotiations. Since there are several things we need to do differently during the first handshake, it is better to have an explicit mIsFirstHandshake flag, and then use that for everything, rather than have a different way of indicating first handshake for every different need (in this case, null timestamp). Please do that and then replace the timestamp.IsNull() and mHandshakeTimestamp = TimeStamp() with that.

@@ +182,5 @@
> +  mHandshakeCompleted = true;
> +  if (!mHandshakeTimestamp.IsNull()) {
> +    TimeDuration elapsed = TimeStamp::Now() - mHandshakeTimestamp;
> +    // This will include TCP and proxy tunnel wait time
> +    Telemetry::Accumulate(Telemetry::SSL_TIME_UNTIL_READY,

Use Telemetry::AccumulateTimeDelta instead.

::: security/manager/ssl/src/nsNSSIOLayer.h
@@ +101,5 @@
>    bool      mHandshakeCompleted;
>    bool      mJoined;
>    bool      mSentClientCert;
> +
> +  mozilla::TimeStamp mHandshakeTimestamp;

The name "handshake timestamp" is unclear. How about:

// This will include TCP and proxy tunnel wait time
const mozilla::TimeStamp mSocketCreationTimestamp;

::: toolkit/components/telemetry/Histograms.json
@@ +712,5 @@
>      "description": "SSL Version (0=unknown, 1=ssl2, 2=ssl3, 3=tls1.0, 4=tls1.1)"
>    },
> +  "SSL_TIME_UNTIL_READY": {
> +    "kind": "exponential",
> +    "high": "5000",

I don't think 5sec is nearly enough, sadly. Why not 1min?

Comment 13

[Brian Smith (:briansmith, :bsmith, use NEEDINFO?)]

Comment on attachment 681101 [details] [diff] [review]
patch 3 ocsp rev 0

Review of attachment 681101 [details] [diff] [review]:
-----------------------------------------------------------------

r+ with review comments addressed.

These numbers would be a lot more useful in conjunction with OCSP cache hit rate numbers and if we could break out OCSP requests blocking SSL connections from OCSP requests not blocking SSL connections. I'll look into doing that after Camilo completes his cert validation callback work.

::: security/manager/ssl/src/nsNSSCallbacks.cpp
@@ +18,5 @@
>  #include "nsIConsoleService.h"
>  #include "nsIHttpChannelInternal.h"
>  #include "nsCRT.h"
>  #include "mozilla/Telemetry.h"
> +#include "mozilla/TimeStamp.h"

Please sort this to the top.

@@ +426,5 @@
>        }
>      }
>    }
>  
> +  if (!event->mStartTime.IsNull()) {

Let's also measure how often this condition is false (e.g. in the ...REQUEST_RESULT probe.)

@@ +427,5 @@
>      }
>    }
>  
> +  if (!event->mStartTime.IsNull()) {
> +    TimeDuration elapsed = TimeStamp::Now() - event->mStartTime;

Please use AccumulateDuration when possible.

@@ +430,5 @@
> +  if (!event->mStartTime.IsNull()) {
> +    TimeDuration elapsed = TimeStamp::Now() - event->mStartTime;
> +
> +    if (request_canceled) {
> +      Telemetry::Accumulate(Telemetry::SSL_SUPPORTING_REQUEST_RESULT, 0);

I suggest we just call these probes CERT_VALIDATION_HTTP_REQUEST_*** instead of SSL_SUPPORTING_REQUEST_***. If/when we add support for other types of requests, we will differentiate them and measure them independently. And, also, these callbacks are used for all cert validations, not just ones for SSL connections

@@ +435,5 @@
> +      Telemetry::Accumulate(Telemetry::SSL_SUPPORTING_REQUEST_CANCELED_TIME,
> +                            static_cast<unsigned int>(elapsed.ToMilliseconds()));
> +    }
> +    else if (NS_SUCCEEDED(mListener->mResultCode) &&
> +        mListener->mHttpResponseCode == 200) {

fix indention of the second line.

::: toolkit/components/telemetry/Histograms.json
@@ +744,5 @@
> +    "description": "ms elapsed time of OCSP etc.. that succeeded"
> +  },
> +  "SSL_SUPPORTING_REQUEST_FAILED_TIME": {
> +    "kind": "exponential",
> +    "high": "5000",

again, I don't think that 5000ms is enough time.

Please s/SSL_SUPPORTING/CERT_VALIDATION_HTTP/ because these are not measuring only SSL requests.

Comment 14

[Brian Smith (:briansmith, :bsmith, use NEEDINFO?)]

Comment on attachment 681138 [details] [diff] [review]
patch 4 key exchange telemetry rev 0

Review of attachment 681138 [details] [diff] [review]:
-----------------------------------------------------------------

::: security/manager/ssl/src/nsNSSCallbacks.cpp
@@ +987,5 @@
> +      SSLCipherSuiteInfo cipherInfo;
> +      if (SSL_GetCipherSuiteInfo(channelInfo.cipherSuite, &cipherInfo,
> +                                 sizeof (cipherInfo)) == SECSuccess) {
> +        // We can use SSLKEAType directly unless those enums change at some
> +        // point in the future

Remove comment.

Comment 15

[Patrick McManus [:mcmanus]]

Attachment: patch 0 version rev 1

Comment 16

[Patrick McManus [:mcmanus]]

Comment on attachment 683716 [details] [diff] [review]
patch 0 version rev 1

r=bsmith r?honzab

Comment 17

[Patrick McManus [:mcmanus]]

(In reply to Brian Smith (:bsmith) from comment #11)

> ::: security/manager/ssl/src/nsNSSCallbacks.cpp
> @@ +930,5 @@
> > +    if (SSL_GetNextProto(fd, &state, npnbuf, &npnlen, 256) == SECSuccess) {
> > +      if (state == SSL_NEXT_PROTO_NEGOTIATED)
> > +        infoObject->SetNegotiatedNPN(reinterpret_cast<char *>(npnbuf), npnlen);
> > +      else
> > +        infoObject->SetNegotiatedNPN(nullptr, 0);
> 
> It seems like the else is not needed and should be removed.
>

It is necessary because it sets mNPNCompleted to true in nsNSSIOLayer.cpp (this is unchanged from the existing code)

Comment 18

[Patrick McManus [:mcmanus]]

Attachment: patch 1 npn rev 1

Comment 19

[Patrick McManus [:mcmanus]]

Comment on attachment 683734 [details] [diff] [review]
patch 1 npn rev 1

r=bsmith r?honzab

Comment 20

[Patrick McManus [:mcmanus]]

Attachment: patch 2 timing rev 1

The only thing I didn't quite do verbatim from the comments was the location of the include.. I read the comments to imply things were already organized in an alphabetical way but I didn't see that at all and I'm not going to make those kinds of changes to reorg existing includes in this patch. I did move up my addition a bit.

Comment 21

[Honza Bambas (:mayhemer)]

Comment on attachment 683716 [details] [diff] [review]
patch 0 version rev 1

Review of attachment 683716 [details] [diff] [review]:
-----------------------------------------------------------------

::: security/manager/ssl/src/nsNSSCallbacks.cpp
@@ +935,5 @@
> +    SSLChannelInfo channelInfo;
> +    if (SSL_GetChannelInfo(fd, &channelInfo, sizeof(channelInfo)) == SECSuccess) {
> +      // Get the protocol version for telemetry
> +      // 0=ssl3, 1=tls1, 2=tls1.1, 3=tls1.2
> +      unsigned int versionEnum = channelInfo.protocolVersion & 0xFF;

channelInfo.protocolVersion & 0xFF seems to be the minor part of the version number.  I don't remember how ssl3 and tls1 are represented, but it seems to me this is not enough to distinguish.

Patrick, can you check this?

See http://hg.mozilla.org/mozilla-central/annotate/4f19e7fd8bea/security/nss/cmd/tstclnt/tstclnt.c#l115

Comment 22

[Honza Bambas (:mayhemer)]

Comment on attachment 683734 [details] [diff] [review]
patch 1 npn rev 1

Review of attachment 683734 [details] [diff] [review]:
-----------------------------------------------------------------

r=honzab with the comment fixed

::: security/manager/ssl/src/nsNSSCallbacks.cpp
@@ +928,5 @@
> +      if (state == SSL_NEXT_PROTO_NEGOTIATED)
> +        infoObject->SetNegotiatedNPN(reinterpret_cast<char *>(npnbuf), npnlen);
> +      else
> +        infoObject->SetNegotiatedNPN(nullptr, 0);
> +      mozilla::Telemetry::Accumulate(Telemetry::SSL_NPN_TYPE, state);

You have to call infoObject->SetNegotiatedNPN(nullptr, 0); also when SSL_GetNextProto fails.

Comment 23

[Honza Bambas (:mayhemer)]

Comment on attachment 681101 [details] [diff] [review]
patch 3 ocsp rev 0

Review of attachment 681101 [details] [diff] [review]:
-----------------------------------------------------------------

r=honzab

Comment 24

[Honza Bambas (:mayhemer)]

Comment on attachment 681138 [details] [diff] [review]
patch 4 key exchange telemetry rev 0

Review of attachment 681138 [details] [diff] [review]:
-----------------------------------------------------------------

r=honzab

::: security/manager/ssl/src/nsNSSCallbacks.cpp
@@ +991,5 @@
> +        // point in the future
> +        // keyExchange null=0, rsa=1, dh=2, fortezza=3, ecdh=4
> +        Telemetry::Accumulate(Telemetry::SSL_KEY_EXCHANGE_ALGORITHM,
> +                              cipherInfo.keaType);
> +      }

Could (should) we do this regardless of whether SSL_GetChannelInfo failed?

Comment 25

[Patrick McManus [:mcmanus]]

(In reply to Honza Bambas (:mayhemer) from comment #21)

> channelInfo.protocolVersion & 0xFF seems to be the minor part of the version
> number.  I don't remember how ssl3 and tls1 are represented, but it seems to
> me this is not enough to distinguish.
> 
> Patrick, can you check this?

as long as we don't start doing SSL2, I think we're good!

./lib/ssl/sslproto.h:#define SSL_LIBRARY_VERSION_2                      0x0002
./lib/ssl/sslproto.h:#define SSL_LIBRARY_VERSION_3_0                    0x0300
./lib/ssl/sslproto.h:#define SSL_LIBRARY_VERSION_TLS_1_0                0x0301
./lib/ssl/sslproto.h:#define SSL_LIBRARY_VERSION_TLS_1_1                0x0302

Comment 26

[Patrick McManus [:mcmanus]]

patches 0, 1, 3, 4 (not 2)

remote:   https://hg.mozilla.org/integration/mozilla-inbound/rev/31728171c90f
remote:   https://hg.mozilla.org/integration/mozilla-inbound/rev/65b16570e960
remote:   https://hg.mozilla.org/integration/mozilla-inbound/rev/10ca2c6b9db3
remote:   https://hg.mozilla.org/integration/mozilla-inbound/rev/eee77a95dbed

Comment 27

[Brian Smith (:briansmith, :bsmith, use NEEDINFO?)]

Comment on attachment 683739 [details] [diff] [review]
patch 2 timing rev 1

Review of attachment 683739 [details] [diff] [review]:
-----------------------------------------------------------------

::: security/manager/ssl/src/nsNSSIOLayer.cpp
@@ +192,5 @@
> +    // This will include TCP and proxy tunnel wait time
> +    Telemetry::AccumulateTimeDelta(Telemetry::SSL_TIME_UNTIL_READY,
> +                                   mSocketCreationTimestamp, TimeStamp::Now());
> +  }
> +  mHandshakeCompleted = true;

Nit: might as well put the assignment within the if block.

Comment 28

[Patrick McManus [:mcmanus]]

patch 2

remote:   https://hg.mozilla.org/integration/mozilla-inbound/rev/7c1277d4480a

Comment 29

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/31728171c90f
https://hg.mozilla.org/mozilla-central/rev/65b16570e960
https://hg.mozilla.org/mozilla-central/rev/10ca2c6b9db3
https://hg.mozilla.org/mozilla-central/rev/eee77a95dbed
https://hg.mozilla.org/mozilla-central/rev/7c1277d4480a