Bug 1737198 - Part 2: Test connection cycling. r=valentin,necko-reviewers

This adds a feature to moz-http2's doh path that helps test connection
cycling. We log the remote ports of DoH requests and expose an API to
fetch the log. A specific name will trigger us to send a delayed response
to help simulate network volatility. The log is then checked for correctness
in the test script.

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

netwerk/test/unit/test_odoh.js

@@ -261,3 +261,5 @@ add_task(test_ipv6_trr_fallback);
 add_task(test_ipv4_trr_fallback);
 
 add_task(test_no_retry_without_doh);
+
+add_task(test_connection_reuse_and_cycling).skip(); // Bug 1742743

netwerk/test/unit/test_trr.js

@@ -893,3 +893,5 @@ add_task(async function test_padding() {
     "1.1.0.160"
   );
 });
+
+add_task(test_connection_reuse_and_cycling);

netwerk/test/unit/trr_common.js

@@ -935,3 +935,158 @@ async function test_no_retry_without_doh() {
   await test(`http://unknown.ipv4.stuff:666/path`, "0.0.0.0");
   await test(`http://unknown.ipv6.stuff:666/path`, "::");
 }
+
+async function test_connection_reuse_and_cycling() {
+  dns.clearCache(true);
+  Services.prefs.setIntPref("network.trr.request_timeout_ms", 500);
+  Services.prefs.setIntPref("network.trr.request_timeout_mode_trronly_ms", 500);
+
+  setModeAndURI(2, `doh?responseIP=9.8.7.6`);
+  Services.prefs.setBoolPref("network.trr.strict_native_fallback", true);
+  Services.prefs.setCharPref("network.trr.confirmationNS", "example.com");
+  await TestUtils.waitForCondition(
+    // 2 => CONFIRM_OK
+    () => dns.currentTrrConfirmationState == 2,
+    `Timed out waiting for confirmation success. Currently ${dns.currentTrrConfirmationState}`,
+    1,
+    5000
+  );
+
+  // Setting conncycle=true in the URI. Server will start logging reqs.
+  // We will do a specific sequence of lookups, then fetch the log from
+  // the server and check that it matches what we'd expect.
+  setModeAndURI(2, `doh?responseIP=9.8.7.6&conncycle=true`);
+  await TestUtils.waitForCondition(
+    // 2 => CONFIRM_OK
+    () => dns.currentTrrConfirmationState == 2,
+    `Timed out waiting for confirmation success. Currently ${dns.currentTrrConfirmationState}`,
+    1,
+    5000
+  );
+  // Confirmation upon uri-change will have created one req.
+
+  // Two reqs for each bar1 and bar2 - A + AAAA.
+  await new TRRDNSListener("bar1.example.org.", "9.8.7.6");
+  await new TRRDNSListener("bar2.example.org.", "9.8.7.6");
+  // Total so far: (1) + 2 + 2 = 5
+
+  // Two reqs that fail, one Confirmation req, two retried reqs that succeed.
+  await new TRRDNSListener("newconn.example.org.", "9.8.7.6");
+  await TestUtils.waitForCondition(
+    // 2 => CONFIRM_OK
+    () => dns.currentTrrConfirmationState == 2,
+    `Timed out waiting for confirmation success. Currently ${dns.currentTrrConfirmationState}`,
+    1,
+    5000
+  );
+  // Total so far: (5) + 2 + 1 + 2 = 10
+
+  // Two reqs for each bar3 and bar4 .
+  await new TRRDNSListener("bar3.example.org.", "9.8.7.6");
+  await new TRRDNSListener("bar4.example.org.", "9.8.7.6");
+  // Total so far: (10) + 2 + 2 = 14.
+
+  // Two reqs that fail, one Confirmation req, two retried reqs that succeed.
+  await new TRRDNSListener("newconn2.example.org.", "9.8.7.6");
+  await TestUtils.waitForCondition(
+    // 2 => CONFIRM_OK
+    () => dns.currentTrrConfirmationState == 2,
+    `Timed out waiting for confirmation success. Currently ${dns.currentTrrConfirmationState}`,
+    1,
+    5000
+  );
+  // Total so far: (14) + 2 + 1 + 2 = 19
+
+  // Two reqs for each bar5 and bar6 .
+  await new TRRDNSListener("bar5.example.org.", "9.8.7.6");
+  await new TRRDNSListener("bar6.example.org.", "9.8.7.6");
+  // Total so far: (19) + 2 + 2 = 23
+
+  let chan = makeChan(
+    `https://foo.example.com:${h2Port}/get-doh-req-port-log`,
+    Ci.nsIRequest.TRR_DISABLED_MODE
+  );
+  let dohReqPortLog = await new Promise(resolve =>
+    chan.asyncOpen(
+      new ChannelListener((stuff, buffer) => {
+        resolve(JSON.parse(buffer));
+      })
+    )
+  );
+
+  // Since the actual ports seen will vary at runtime, we use placeholders
+  // instead in our expected output definition. For example, if two entries
+  // both have "port1", it means they both should have the same port in the
+  // server's log.
+  // For reqs that fail and trigger a Confirmation + retry, the retried reqs
+  // might not re-use the new connection created for Confirmation due to a
+  // race, so we have an extra alternate expected port for them. This lets
+  // us test that they use *a* new port even if it's not *the* new port.
+  // Subsequent lookups are not affected, they will use the same conn as
+  // the Confirmation req.
+  let expectedLogTemplate = [
+    ["example.com", "port1"],
+    ["bar1.example.org", "port1"],
+    ["bar1.example.org", "port1"],
+    ["bar2.example.org", "port1"],
+    ["bar2.example.org", "port1"],
+    ["newconn.example.org", "port1"],
+    ["newconn.example.org", "port1"],
+    ["example.com", "port2"],
+    ["newconn.example.org", "port2"],
+    ["newconn.example.org", "port2"],
+    ["bar3.example.org", "port2"],
+    ["bar3.example.org", "port2"],
+    ["bar4.example.org", "port2"],
+    ["bar4.example.org", "port2"],
+    ["newconn2.example.org", "port2"],
+    ["newconn2.example.org", "port2"],
+    ["example.com", "port3"],
+    ["newconn2.example.org", "port3"],
+    ["newconn2.example.org", "port3"],
+    ["bar5.example.org", "port3"],
+    ["bar5.example.org", "port3"],
+    ["bar6.example.org", "port3"],
+    ["bar6.example.org", "port3"],
+  ];
+
+  if (expectedLogTemplate.length != dohReqPortLog.length) {
+    // This shouldn't happen, and if it does, we'll fail the assertion
+    // below. But first dump the whole server-side log to help with
+    // debugging should we see a failure. Most likely cause would be
+    // that another consumer of TRR happened to make a request while
+    // the test was running and polluted the log.
+    info(dohReqPortLog);
+  }
+
+  equal(
+    expectedLogTemplate.length,
+    dohReqPortLog.length,
+    "Correct number of req log entries"
+  );
+
+  let seenPorts = new Set();
+  // This is essentially a symbol table - as we iterate through the log
+  // we will assign the actual seen port numbers to the placeholders.
+  let seenPortsByExpectedPort = new Map();
+
+  for (let i = 0; i < expectedLogTemplate.length; i++) {
+    let expectedName = expectedLogTemplate[i][0];
+    let expectedPort = expectedLogTemplate[i][1];
+    let seenName = dohReqPortLog[i][0];
+    let seenPort = dohReqPortLog[i][1];
+    info(`Checking log entry. Name: ${seenName}, Port: ${seenPort}`);
+    equal(expectedName, seenName, "Name matches for entry " + i);
+    if (!seenPortsByExpectedPort.has(expectedPort)) {
+      ok(!seenPorts.has(seenPort), "Port should not have been previously used");
+      seenPorts.add(seenPort);
+      seenPortsByExpectedPort.set(expectedPort, seenPort);
+    } else {
+      equal(
+        seenPort,
+        seenPortsByExpectedPort.get(expectedPort),
+        "Connection was reused as expected"
+      );
+    }
+  }
+}

testing/xpcshell/moz-http2/moz-http2.js

@@ -234,6 +234,9 @@ var didRst = false;
 var rstConnection = null;
 var illegalheader_conn = null;
 
+var gDoHPortsLog = [];
+var gDoHNewConnLog = {};
+
 // eslint-disable-next-line complexity
 function handleRequest(req, res) {
   // We do this first to ensure nothing goes wonky in our tests that don't want
@@ -510,14 +513,22 @@ function handleRequest(req, res) {
         zlib.gzip(buffer, function(err, result) {
           resp.setHeader("Content-Encoding", "gzip");
           resp.setHeader("Content-Length", result.length);
-          resp.writeHead(200);
-          res.end(result);
+          try {
+            resp.writeHead(200);
+            resp.end(result);
+          } catch (e) {
+            // connection was closed by the time we started writing.
+          }
         });
       } else {
         resp.setHeader("Content-Length", buffer.length);
-        resp.writeHead(200);
-        resp.write(buffer);
-        resp.end("");
+        try {
+          resp.writeHead(200);
+          resp.write(buffer);
+          resp.end("");
+        } catch (e) {
+          // connection was closed by the time we started writing.
+        }
       }
     }
 
@@ -883,6 +894,13 @@ function handleRequest(req, res) {
       emitResponse(res, payload);
     });
     return;
+  } else if (u.pathname == "/get-doh-req-port-log") {
+    let rContent = JSON.stringify(gDoHPortsLog);
+    res.setHeader("Content-Type", "text/plain");
+    res.setHeader("Content-Length", rContent.length);
+    res.writeHead(400);
+    res.end(rContent);
+    return;
   } else if (u.pathname == "/doh") {
     let responseIP = u.query.responseIP;
     if (!responseIP) {
@@ -962,8 +980,8 @@ function handleRequest(req, res) {
 
     let payload = Buffer.from("");
 
-    function emitResponse(response, requestPayload) {
-      let packet = dnsPacket.decode(requestPayload);
+    function emitResponse(response, requestPayload, decodedPacket, delay) {
+      let packet = decodedPacket || dnsPacket.decode(requestPayload);
       let answer = createDNSAnswer(
         response,
         packet,
@@ -976,7 +994,7 @@ function handleRequest(req, res) {
       writeDNSResponse(
         response,
         answer,
-        getDelayFromPacket(packet, responseType(packet, responseIP)),
+        delay || getDelayFromPacket(packet, responseType(packet, responseIP)),
         "application/dns-message"
       );
     }
@@ -993,7 +1011,30 @@ function handleRequest(req, res) {
     req.on("end", function finishedData() {
       // parload is empty when we send redirect response.
       if (payload.length) {
-        emitResponse(res, payload);
+        let packet = dnsPacket.decode(payload);
+        let delay;
+        if (u.query.conncycle) {
+          let name = packet.questions[0].name;
+          if (name.startsWith("newconn")) {
+            // If we haven't seen a req for this newconn name before,
+            // or if we've seen one for the same name on the same port,
+            // synthesize a timeout.
+            if (
+              !gDoHNewConnLog[name] ||
+              gDoHNewConnLog[name] == req.remotePort
+            ) {
+              delay = 1000;
+            }
+            if (!gDoHNewConnLog[name]) {
+              gDoHNewConnLog[name] = req.remotePort;
+            }
+          }
+          gDoHPortsLog.push([packet.questions[0].name, req.remotePort]);
+        } else {
+          gDoHPortsLog = [];
+          gDoHNewConnLog = {};
+        }
+        emitResponse(res, payload, packet, delay);
       }
     });
     return;