Bug 1822876: Add H3 ECH Telemetry. r=kershaw,necko-reviewers

This patch adds telemetry which records when H3 connections succeed / fail
and what kind of ECH they used. Our H3 ECH tests are extended to test these
different modes and that the telemetry is recorded correctly.

Differential Revision: https://phabricator.services.mozilla.com/D172813

netwerk/protocol/http/Http3Session.cpp

@@ -178,10 +178,12 @@ nsresult Http3Session::Init(const nsHttpConnectionInfo* aConnInfo,
           100 - StaticPrefs::security_tls_ech_grease_probability()) {
         // Setting an empty config enables GREASE mode.
         mSocketControl->SetEchConfig(config);
+        mEchExtensionStatus = EchExtensionStatus::kGREASE;
       }
     }
   } else if (gHttpHandler->EchConfigEnabled(true) && !config.IsEmpty()) {
     mSocketControl->SetEchConfig(config);
+    mEchExtensionStatus = EchExtensionStatus::kReal;
     HttpConnectionActivity activity(
         mConnInfo->HashKey(), mConnInfo->GetOrigin(), mConnInfo->OriginPort(),
         mConnInfo->EndToEndSSL(), !mConnInfo->GetEchConfig().IsEmpty(),
@@ -189,6 +191,8 @@ nsresult Http3Session::Init(const nsHttpConnectionInfo* aConnInfo,
     gHttpHandler->ObserveHttpActivityWithArgs(
         activity, NS_ACTIVITY_TYPE_HTTP_CONNECTION,
         NS_HTTP_ACTIVITY_SUBTYPE_ECH_SET, PR_Now(), 0, ""_ns);
+  } else {
+    mEchExtensionStatus = EchExtensionStatus::kNotPresent;
   }
 
   // After this line, Http3Session and HttpConnectionUDP become a cycle. We put
@@ -199,7 +203,8 @@ nsresult Http3Session::Init(const nsHttpConnectionInfo* aConnInfo,
 }
 
 void Http3Session::DoSetEchConfig(const nsACString& aEchConfig) {
-  LOG(("Http3Session::DoSetEchConfig %p", this));
+  LOG(("Http3Session::DoSetEchConfig %p of length %zu", this,
+       aEchConfig.Length()));
   nsTArray<uint8_t> config;
   config.AppendElements(
       reinterpret_cast<const uint8_t*>(aEchConfig.BeginReading()),
@@ -287,6 +292,7 @@ void Http3Session::Shutdown() {
 Http3Session::~Http3Session() {
   LOG3(("Http3Session::~Http3Session %p", this));
 
+  EchOutcomeTelemetry();
   Telemetry::Accumulate(Telemetry::HTTP3_REQUEST_PER_CONN, mTransactionCount);
   Telemetry::Accumulate(Telemetry::HTTP3_BLOCKED_BY_STREAM_LIMIT_PER_CONN,
                         mBlockedByStreamLimitCount);
@@ -2078,6 +2084,7 @@ void Http3Session::SetSecInfo() {
 
     mSocketControl->SetInfo(secInfo.cipher, secInfo.version, secInfo.group,
                             secInfo.signature_scheme, secInfo.ech_accepted);
+    mHandshakeSucceeded = true;
   }
 
   if (!mSocketControl->HasServerCert()) {
@@ -2282,6 +2289,26 @@ void Http3Session::ReportHttp3Connection() {
   }
 }
 
+void Http3Session::EchOutcomeTelemetry() {
+  MOZ_ASSERT(OnSocketThread(), "not on socket thread");
+
+  nsAutoCString key;
+  switch (mEchExtensionStatus) {
+    case EchExtensionStatus::kNotPresent:
+      key = "NONE";
+      break;
+    case EchExtensionStatus::kGREASE:
+      key = "GREASE";
+      break;
+    case EchExtensionStatus::kReal:
+      key = "REAL";
+      break;
+  }
+
+  Telemetry::Accumulate(Telemetry::HTTP3_ECH_OUTCOME, key,
+                        mHandshakeSucceeded ? 0 : 1);
+}
+
 void Http3Session::ZeroRttTelemetry(ZeroRttOutcome aOutcome) {
   Telemetry::Accumulate(Telemetry::HTTP3_0RTT_STATE, aOutcome);
 

netwerk/protocol/http/Http3Session.h

@@ -113,6 +113,12 @@ class QuicSocketControl;
     }                                                \
   }
 
+enum class EchExtensionStatus {
+  kNotPresent,  // No ECH Extension was sent
+  kGREASE,      // A GREASE ECH Extension was sent
+  kReal         // A 'real' ECH Extension was sent
+};
+
 class Http3Session final : public nsAHttpTransaction, public nsAHttpConnection {
  public:
   NS_DECLARE_STATIC_IID_ACCESSOR(NS_HTTP3SESSION_IID)
@@ -239,6 +245,8 @@ class Http3Session final : public nsAHttpTransaction, public nsAHttpConnection {
   void CallCertVerification(Maybe<nsCString> aEchPublicName);
   void SetSecInfo();
 
+  void EchOutcomeTelemetry();
+
   void StreamReadyToWrite(Http3StreamBase* aStream);
   void MaybeResumeSend();
 
@@ -330,6 +338,13 @@ class Http3Session final : public nsAHttpTransaction, public nsAHttpConnection {
   int64_t mTotalBytesWritten = 0;  // total data read
   PRIntervalTime mLastWriteTime = 0;
 
+  // Records whether we sent an ECH Extension and whether it was a GREASE Xtn
+  EchExtensionStatus mEchExtensionStatus = EchExtensionStatus::kNotPresent;
+
+  // Records whether the handshake finished successfully and we established a
+  // a connection.
+  bool mHandshakeSucceeded = false;
+
   nsCOMPtr<nsINetAddr> mNetAddr;
 
   enum WebTransportNegotiation { DISABLED, NEGOTIATING, FAILED, SUCCEEDED };

netwerk/test/unit/head_telemetry.js

@@ -56,32 +56,23 @@ var HandshakeTelemetryHelpers = {
       !mozinfo.socketprocess_networking,
       "Histograms don't populate on network process"
     );
-    let snapshot = JSON.parse(JSON.stringify(histogram.snapshot()));
+    let snapshot = JSON.parse(JSON.stringify(histogram));
     for (let [Tk, Tv] of expectedEntries.entries()) {
       let found = false;
       for (let [i, val] of Object.entries(snapshot.values)) {
         if (i == Tk) {
           found = true;
-          Assert.equal(
-            val,
-            Tv,
-            `expected counts should match for ${histogram.name()} at index ${i}`
-          );
+          Assert.equal(val, Tv, `expected counts should match at index ${i}`);
           snapshot.values[i] = 0; // Reset the value
         }
       }
-      Assert.ok(
-        found,
-        `Should have found an entry for ${histogram.name()} at index ${Tk}`
-      );
+      Assert.ok(found, `Should have found an entry at index ${Tk}`);
     }
     for (let k in snapshot.values) {
       Assert.equal(
         snapshot.values[k],
         0,
-        `Should NOT have found an entry for ${histogram.name()} at index ${k} of value ${
-          snapshot.values[k]
-        }`
+        `Should NOT have found an entry at index ${k} of value ${snapshot.values[k]}`
       );
     }
   },

netwerk/test/unit/test_httpssvc_retry_with_ech.js

@@ -72,6 +72,8 @@ registerCleanupFunction(async () => {
   Services.prefs.clearUserPref("network.dns.echconfig.fallback_to_origin");
   Services.prefs.clearUserPref("network.http.speculative-parallel-limit");
   Services.prefs.clearUserPref("network.dns.port_prefixed_qname_https_rr");
+  Services.prefs.clearUserPref("security.tls.ech.grease_http3");
+  Services.prefs.clearUserPref("security.tls.ech.grease_probability");
   if (trrServer) {
     await trrServer.stop();
   }
@@ -131,7 +133,7 @@ ActivityObserver.prototype = {
   },
 };
 
-function checkHttpActivities(activites) {
+function checkHttpActivities(activites, expectECH) {
   let foundDNSAndSocket = false;
   let foundSettingECH = false;
   let foundConnectionCreated = false;
@@ -154,7 +156,7 @@ function checkHttpActivities(activites) {
   }
 
   Assert.equal(foundDNSAndSocket, true, "Should have one DnsAndSock created");
-  Assert.equal(foundSettingECH, true, "Should have echConfig");
+  Assert.equal(foundSettingECH, expectECH, "Should have echConfig");
   Assert.equal(
     foundConnectionCreated,
     true,
@@ -238,7 +240,7 @@ add_task(async function testConnectWithECH() {
   let filtered = observer.activites.filter(
     activity => activity.host === "ech-private.example.com"
   );
-  checkHttpActivities(filtered);
+  checkHttpActivities(filtered, true);
 });
 
 add_task(async function testEchRetry() {
@@ -311,7 +313,7 @@ add_task(async function testEchRetry() {
     for (let hName of ["SSL_HANDSHAKE_RESULT", "SSL_HANDSHAKE_RESULT_ECH"]) {
       let h = Services.telemetry.getHistogramById(hName);
       HandshakeTelemetryHelpers.assertHistogramMap(
-        h,
+        h.snapshot(),
         new Map([
           ["0", 1],
           ["188", 1],
@@ -325,7 +327,17 @@ add_task(async function testEchRetry() {
   await trrServer.stop();
 });
 
-async function H3ECHTest(echConfig) {
+async function H3ECHTest(
+  echConfig,
+  expectedHistKey,
+  expectedHistEntries,
+  advertiseECH
+) {
+  Services.dns.clearCache(true);
+  Services.obs.notifyObservers(null, "net:cancel-all-connections");
+  /* eslint-disable mozilla/no-arbitrary-setTimeout */
+  await new Promise(resolve => setTimeout(resolve, 1000));
+  resetEchTelemetry();
   trrServer = new TRRServer();
   await trrServer.start();
 
@@ -338,12 +350,27 @@ async function H3ECHTest(echConfig) {
   let observerService = Cc[
     "@mozilla.org/network/http-activity-distributor;1"
   ].getService(Ci.nsIHttpActivityDistributor);
+  Services.obs.notifyObservers(null, "net:cancel-all-connections");
   let observer = new ActivityObserver();
   observerService.addObserver(observer);
   observerService.observeConnection = true;
+  // Clear activities for past connections
+  observer.activites = [];
 
   let portPrefixedName = `_${h3Port}._https.public.example.com`;
+  let vals = [
+    { key: "alpn", value: "h3-29" },
+    { key: "port", value: h3Port },
+  ];
+  if (advertiseECH) {
+    vals.push({
+      key: "echconfig",
+      value: echConfig,
+      needBase64Decode: true,
+    });
+  }
   // Only the last record is valid to use.
+
   await trrServer.registerDoHAnswers(portPrefixedName, "HTTPS", {
     answers: [
       {
@@ -354,15 +381,7 @@ async function H3ECHTest(echConfig) {
         data: {
           priority: 1,
           name: ".",
-          values: [
-            { key: "alpn", value: "h3-29" },
-            { key: "port", value: h3Port },
-            {
-              key: "echconfig",
-              value: echConfig,
-              needBase64Decode: true,
-            },
-          ],
+          values: vals,
         },
       },
     ],
@@ -389,7 +408,7 @@ async function H3ECHTest(echConfig) {
   let [req] = await channelOpenPromise(chan, CL_ALLOW_UNKNOWN_CL);
   req.QueryInterface(Ci.nsIHttpChannel);
   Assert.equal(req.protocolVersion, "h3-29");
-  checkSecurityInfo(chan, true, true);
+  checkSecurityInfo(chan, true, advertiseECH);
 
   await trrServer.stop();
 
@@ -399,14 +418,67 @@ async function H3ECHTest(echConfig) {
   let filtered = observer.activites.filter(
     activity => activity.host === "public.example.com"
   );
-  checkHttpActivities(filtered);
+  checkHttpActivities(filtered, advertiseECH);
+  await checkEchTelemetry(expectedHistKey, expectedHistEntries);
 }
 
-add_task(async function testH3ConnectWithECH() {
-  await H3ECHTest(h3EchConfig);
+function resetEchTelemetry() {
+  Services.telemetry.getKeyedHistogramById("HTTP3_ECH_OUTCOME").clear();
+}
+
+async function checkEchTelemetry(histKey, histEntries) {
+  Services.obs.notifyObservers(null, "net:cancel-all-connections");
+  /* eslint-disable mozilla/no-arbitrary-setTimeout */
+  await new Promise(resolve => setTimeout(resolve, 1000));
+  let values = Services.telemetry
+    .getKeyedHistogramById("HTTP3_ECH_OUTCOME")
+    .snapshot()[histKey];
+  if (!mozinfo.socketprocess_networking) {
+    HandshakeTelemetryHelpers.assertHistogramMap(values, histEntries);
+  }
+}
+
+add_task(async function testH3WithNoEch() {
+  Services.prefs.setBoolPref("security.tls.ech.grease_http3", false);
+  Services.prefs.setIntPref("security.tls.ech.grease_probability", 0);
+  await H3ECHTest(
+    h3EchConfig,
+    "NONE",
+    new Map([
+      ["0", 1],
+      ["1", 0],
+    ]),
+    false
+  );
 });
 
-add_task(async function testH3ConnectWithECHRetry() {
+add_task(async function testH3WithECH() {
+  await H3ECHTest(
+    h3EchConfig,
+    "REAL",
+    new Map([
+      ["0", 1],
+      ["1", 0],
+    ]),
+    true
+  );
+});
+
+add_task(async function testH3WithGreaseEch() {
+  Services.prefs.setBoolPref("security.tls.ech.grease_http3", true);
+  Services.prefs.setIntPref("security.tls.ech.grease_probability", 100);
+  await H3ECHTest(
+    h3EchConfig,
+    "GREASE",
+    new Map([
+      ["0", 1],
+      ["1", 0],
+    ]),
+    false
+  );
+});
+
+add_task(async function testH3WithECHRetry() {
   Services.dns.clearCache(true);
   Services.obs.notifyObservers(null, "net:cancel-all-connections");
   // eslint-disable-next-line mozilla/no-arbitrary-setTimeout
@@ -425,5 +497,13 @@ add_task(async function testH3ConnectWithECHRetry() {
   let decodedConfig = base64ToArray(h3EchConfig);
   decodedConfig[6] ^= 0x94;
   let encoded = btoa(String.fromCharCode.apply(null, decodedConfig));
-  await H3ECHTest(encoded);
+  await H3ECHTest(
+    encoded,
+    "REAL",
+    new Map([
+      ["0", 1],
+      ["1", 1],
+    ]),
+    true
+  );
 });

toolkit/components/telemetry/Histograms.json

@@ -3408,6 +3408,18 @@
     "n_buckets": 200,
     "description": "ms of SSL wait time for full handshake including TCP and proxy tunneling, keyed by the key exchange algorithm used"
   },
+  "HTTP3_ECH_OUTCOME": {
+    "record_in_processes": ["main"],
+    "products": ["firefox", "fennec"],
+    "alert_emails": ["seceng-telemetry@mozilla.com", "necko@mozilla.com", "djackson@mozilla.com"],
+    "bug_numbers": [182287 ],
+    "releaseChannelCollection": "opt-out",
+    "expires_in_version": "never",
+    "kind": "enumerated",
+    "keyed": true,
+    "n_values": 32,
+    "description": "Success / Fail Rates for HTTP3 Keyed by ECH Usage"
+  },
   "SSL_BYTES_BEFORE_CERT_CALLBACK": {
     "record_in_processes": ["main", "content"],
     "products": ["firefox", "fennec"],