Hetzner checks answer again; failed checks go to the console (closes #114)

The Hetzner speed-test servers close the connection without an answer
when the URL has a query string, and every check added ?_cb= and the
time, so all six showed unreachable. Checks now fetch each target's URL
as written; cache: "no-store" still keeps the browser's cache out of the
measurement.

Each recorded check that fails writes one console.error line, and the
same line to the debug log: the target's name and URL, the time, what
failed and how long the request took. A target that answers after
failed checks writes one console.info line. Checks the page does not
record write nothing, so the debug log no longer lists failures in the
first round or the recovery probe.

Model: opus-5-5

test/unit/main.test.js

@@ -23,12 +23,16 @@ import {
 // test looks it up and kept in elements under its selector until the next
 // test starts. As on a page, writing its text replaces its markup; the
 // status dot greyOutUI looks for in it is not there. Drawing a sparkline
-// does nothing; it looks for the pixel ratio on window and finds none.
-let elements;
-beforeEach(() => {
-    elements = {};
-});
+// does nothing; it looks for the pixel ratio on window and finds none. In
+// each test, console.error and console.info print nothing and keep what
+// they are given.
 const doNothing = () => {};
+let elements;
+beforeEach((t) => {
+    elements = {};
+    t.mock.method(console, "error", doNothing);
+    t.mock.method(console, "info", doNothing);
+});
 const canvasContext = {
     clearRect: doNothing,
     beginPath: doNothing,
@@ -69,8 +73,10 @@ function statusText(state, host) {
 // Mocks the clock for test t, so that a check lasting seconds takes no real
 // time, and replaces fetch with targets that each answer after
 // answerAfter(url) milliseconds of that clock, or never when that is
-// Infinity. Both are restored when the test ends.
-function mockTargets(t, answerAfter) {
+// Infinity. The target at unreachableUrl, if one is given, does not
+// answer: after that time its fetch fails with the error a browser gives
+// the page for a network error. Both are restored when the test ends.
+function mockTargets(t, answerAfter, unreachableUrl) {
     t.mock.timers.enable({ apis: ["setTimeout", "Date"] });
     t.mock.method(performance, "now", () => Date.now());
     t.mock.method(
@@ -78,8 +84,12 @@ function mockTargets(t, answerAfter) {
         "fetch",
         (url, { signal }) =>
             new Promise((resolve, reject) => {
+                const answer =
+                    url === unreachableUrl
+                        ? () => reject(new TypeError("Failed to fetch"))
+                        : resolve;
                 if (answerAfter(url) !== Infinity) {
-                    setTimeout(resolve, answerAfter(url));
+                    setTimeout(answer, answerAfter(url));
                 }
                 signal.addEventListener("abort", () => reject(signal.reason));
             }),
@@ -107,6 +117,7 @@ for (const interval of [10000, 30000]) {
         assert.deepEqual(await settled(check), {
             latency: slowAnswer,
             error: null,
+            reason: null,
         });
     });
 
@@ -120,10 +131,37 @@ for (const interval of [10000, 30000]) {
         assert.deepEqual(await settled(check), {
             latency: null,
             error: "timeout",
+            reason: `timed out after ${timeout} ms (limit ${timeout} ms)`,
         });
     });
 }
 
+// A browser can run a timer late, on a busy page or in a background tab.
+// Moving the mocked clock on 30000ms at once runs the 24000ms timeout with
+// the clock already at 30000ms.
+test("at a 30000ms interval, a check whose timeout runs late gives how long the request took and the time limit", async (t) => {
+    CONFIG.updateInterval = 30000;
+    mockTargets(t, () => Infinity);
+    const check = measureLatency("https://target.test");
+    t.mock.timers.tick(30000);
+    assert.deepEqual(await settled(check), {
+        latency: null,
+        error: "timeout",
+        reason: "timed out after 30000 ms (limit 24000 ms)",
+    });
+});
+
+test("a check fetches the target's URL as written, with no query string added", async (t) => {
+    mockTargets(t, () => 10);
+    const check = measureLatency("https://fsn1-speed.hetzner.com");
+    t.mock.timers.tick(10);
+    assert.notEqual(await settled(check), "still waiting");
+    assert.equal(
+        fetch.mock.calls[0].arguments[0],
+        "https://fsn1-speed.hetzner.com",
+    );
+});
+
 test("at a 30000ms interval, a target answering after 1000ms shows in its row while another target's check is still waiting", async (t) => {
     CONFIG.updateInterval = 30000;
     const state = new AppState([
@@ -132,7 +170,7 @@ test("at a 30000ms interval, a target answering after 1000ms shows in its row wh
     const answering = state.local[0];
     const waiting = state.wan[0];
     // No target but the answering one ever answers.
-    mockTargets(t, (url) => (url.startsWith(answering.url) ? 1000 : Infinity));
+    mockTargets(t, (url) => (url === answering.url ? 1000 : Infinity));
     // The third tick: the first is discarded as a whole, and the second ends
     // by sorting the rows, which rebuilds a page that is not here.
     state.tickCount = 2;
@@ -159,7 +197,7 @@ test("at a 30000ms interval, a check still waiting when its round is given up do
         { name: "Answering", url: "https://answering.test" },
     ]);
     const answering = state.local[0];
-    mockTargets(t, (url) => (url.startsWith(answering.url) ? 1000 : Infinity));
+    mockTargets(t, (url) => (url === answering.url ? 1000 : Infinity));
     state.tickCount = 2;
 
     const roundChecks = new AbortController();
@@ -177,7 +215,7 @@ test("at a 30000ms interval, a check still waiting when the user pauses does not
         { name: "Answering", url: "https://answering.test" },
     ]);
     const answering = state.local[0];
-    mockTargets(t, (url) => (url.startsWith(answering.url) ? 1000 : Infinity));
+    mockTargets(t, (url) => (url === answering.url ? 1000 : Infinity));
     state.tickCount = 2;
 
     const round = tick(state, new AbortController().signal);
@@ -194,7 +232,7 @@ test("at a 30000ms interval, a check in the first round does not show in its row
         { name: "Answering", url: "https://answering.test" },
     ]);
     const answering = state.local[0];
-    mockTargets(t, (url) => (url.startsWith(answering.url) ? 1000 : Infinity));
+    mockTargets(t, (url) => (url === answering.url ? 1000 : Infinity));
 
     const round = tick(state, new AbortController().signal);
     t.mock.timers.tick(1000);
@@ -208,7 +246,7 @@ test("at a 30000ms interval, after the user pauses and resumes during a round, n
         { name: "Answering", url: "https://answering.test" },
     ]);
     const answering = state.local[0];
-    mockTargets(t, (url) => (url.startsWith(answering.url) ? 1000 : Infinity));
+    mockTargets(t, (url) => (url === answering.url ? 1000 : Infinity));
     state.tickCount = 2;
 
     const round = tick(state, new AbortController().signal);
@@ -231,6 +269,115 @@ test("at a 30000ms interval, after the user pauses and resumes during a round, n
     }
 });
 
+// In the next tests a round checks one target, Target, at a 30000ms
+// interval, so a check times out after 24000ms. The mocked clock starts at
+// 1970-01-01T00:00:00.000Z.
+
+// An app state with Target and no WAN targets, so its rounds check only
+// Target, and whose next round is recorded: it is the third, as the first
+// is discarded and the second ends by sorting the rows, which rebuilds a
+// page that is not here. Returns it and Target.
+function stateWithOneTarget() {
+    CONFIG.updateInterval = 30000;
+    const state = new AppState([
+        { name: "Target", url: "https://target.test" },
+    ]);
+    state.wan = [];
+    state.tickCount = 2;
+    return { state, target: state.local[0] };
+}
+
+// What this test wrote to the browser console with console[method].
+function consoleLines(method) {
+    return console[method].mock.calls.map((call) => call.arguments[0]);
+}
+
+test("a check that fails with a network error writes one console line with the target, the time, the error and how long the request took", async (t) => {
+    const { state, target } = stateWithOneTarget();
+    mockTargets(t, () => 23, target.url);
+    const round = tick(state, new AbortController().signal);
+    t.mock.timers.tick(23);
+    assert.notEqual(await settled(round), "still waiting");
+    assert.deepEqual(consoleLines("error"), [
+        "netwatch: check failed: Target https://target.test at 1970-01-01T00:00:00.023Z: network error (TypeError: Failed to fetch) after 23 ms",
+    ]);
+    assert.deepEqual(consoleLines("info"), []);
+});
+
+test("a check that times out writes one console line with the target, the time, how long the request took and the time limit", async (t) => {
+    const { state } = stateWithOneTarget();
+    mockTargets(t, () => Infinity);
+    const round = tick(state, new AbortController().signal);
+    t.mock.timers.tick(24000);
+    assert.notEqual(await settled(round), "still waiting");
+    assert.deepEqual(consoleLines("error"), [
+        "netwatch: check failed: Target https://target.test at 1970-01-01T00:00:24.000Z: timed out after 24000 ms (limit 24000 ms)",
+    ]);
+    assert.deepEqual(consoleLines("info"), []);
+});
+
+// An answer that took longer than CONFIG.maxLatency is recorded as a
+// timeout. The limit is the check's own timeout, so such an answer is one
+// that came in just as the check timed out; here it is lowered to 500ms.
+test("a check answered over the time limit writes one console line with the target, the time, how long the answer took and the limit", async (t) => {
+    const { state } = stateWithOneTarget();
+    t.mock.getter(CONFIG, "maxLatency", () => 500);
+    mockTargets(t, () => 1000);
+    const round = tick(state, new AbortController().signal);
+    t.mock.timers.tick(1000);
+    assert.notEqual(await settled(round), "still waiting");
+    assert.deepEqual(consoleLines("error"), [
+        "netwatch: check failed: Target https://target.test at 1970-01-01T00:00:01.000Z: answered after 1000 ms, over the 500 ms limit",
+    ]);
+    assert.deepEqual(consoleLines("info"), []);
+});
+
+test("a check that answers writes nothing to the console", async (t) => {
+    const { state } = stateWithOneTarget();
+    mockTargets(t, () => 30);
+    const round = tick(state, new AbortController().signal);
+    t.mock.timers.tick(30);
+    assert.notEqual(await settled(round), "still waiting");
+    assert.deepEqual(consoleLines("error"), []);
+    assert.deepEqual(consoleLines("info"), []);
+});
+
+for (const [failed, checks] of [
+    [1, "1 failed check"],
+    [3, "3 failed checks"],
+]) {
+    test(`a check that answers after ${checks} writes one console line saying the target recovered, and the next writes nothing`, async (t) => {
+        const { state, target } = stateWithOneTarget();
+        for (let i = 0; i < failed; i++) {
+            target.pushSample(Date.now(), {
+                latency: null,
+                error: "unreachable",
+            });
+        }
+        mockTargets(t, () => 40);
+        for (let i = 0; i < 2; i++) {
+            const round = tick(state, new AbortController().signal);
+            t.mock.timers.tick(40);
+            assert.notEqual(await settled(round), "still waiting");
+        }
+        assert.deepEqual(consoleLines("info"), [
+            `netwatch: target recovered: Target https://target.test at 1970-01-01T00:00:00.040Z: answered after 40 ms, following ${checks} in a row`,
+        ]);
+        assert.deepEqual(consoleLines("error"), []);
+    });
+}
+
+test("a check that fails in the first round, which is discarded, writes nothing to the console", async (t) => {
+    const { state, target } = stateWithOneTarget();
+    state.tickCount = 0;
+    mockTargets(t, () => 23, target.url);
+    const round = tick(state, new AbortController().signal);
+    t.mock.timers.tick(23);
+    assert.notEqual(await settled(round), "still waiting");
+    assert.deepEqual(consoleLines("error"), []);
+    assert.deepEqual(consoleLines("info"), []);
+});
+
 // The page shows &lt; &gt; &quot; &amp; and &#39; in a row's markup as
 // < > " & and '.
 test(`a target whose name and URL hold < > " & and ' shows those characters in its row`, () => {