diff --git a/README.md b/README.md index c3a11e0..32e967c 100644 --- a/README.md +++ b/README.md @@ -188,17 +188,28 @@ Local hosts are tracked separately from WAN stats. ### Latency measurement -GET requests with `mode: 'no-cors'`, `cache: 'no-store'` and a cache-busting -query parameter, timed with `performance.now()`. Each check times out after 80% -of the refresh interval (24 seconds at 30 seconds) and is then recorded as a -timeout, so a round's checks have all finished before the next round is due. -When no WAN host answers, a recovery probe checks 4 WAN hosts, picked at random -when it starts, every half second, giving up the checks it started half a second -before. As soon as one answers, a new round starts at once, as it does after an -interval change. A round started early gives up the last round's checks if they -are still waiting, and that round records nothing more, so rounds never overlap. -The browser chooses between IPv4 and IPv6 for each target, as for any request; -the local targets are IPv4 addresses. +GET requests to each target's URL as written, with `mode: 'no-cors'` and +`cache: 'no-store'`, timed with `performance.now()`. No query string is added: +the Hetzner speed-test servers close the connection without an answer when the +URL has one, and `no-store` keeps the browser's cache out of the measurement. +Each check times out after 80% of the refresh interval (24 seconds at 30 +seconds) and is then recorded as a timeout, so a round's checks have all +finished before the next round is due. When no WAN host answers, a recovery +probe checks 4 WAN hosts, picked at random when it starts, every half second, +giving up the checks it started half a second before. As soon as one answers, a +new round starts at once, as it does after an interval change. A round started +early gives up the last round's checks if they are still waiting, and that round +records nothing more, so rounds never overlap. The browser chooses between IPv4 +and IPv6 for each target, as for any request; the local targets are IPv4 +addresses. + +Each recorded check that fails writes one line to the browser console with +`console.error`, and the same line to the debug log: the target's name and URL, +the time, whether it timed out, answered over the time limit or hit a network +error (with the error the browser gives the page, such as +`TypeError: Failed to fetch`, which does not say why), and how long the request +took. A target that answers after failed checks writes one `console.info` line +with its latency and how many checks in a row had failed. ### Color coding diff --git a/TODO.md b/TODO.md index 91c6e04..3c178e5 100644 --- a/TODO.md +++ b/TODO.md @@ -22,6 +22,17 @@ Decide whether the repo moves to the layout `REPO_POLICIES.md` gives, with # Completed Steps +- 2026-10-07: the six Hetzner targets answer again, and failed checks are + written to the browser console + ([#114](https://git.eeqj.de/sneak/netwatch/issues/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; checks now fetch + each target's URL as written, with `cache: 'no-store'` as before. Each + recorded check that fails writes one `console.error` line, and the same line + to the debug log, with 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 none, so the + debug log no longer lists failures in the first round or in the recovery probe - 2026-10-04: the page's footer no longer says "IPv4 only" ([#111](https://git.eeqj.de/sneak/netwatch/issues/111)): each check is a `fetch`, the browser picks IPv4 or IPv6 for each WAN host, and the local diff --git a/src/main.js b/src/main.js index 03eead7..821e381 100644 --- a/src/main.js +++ b/src/main.js @@ -268,6 +268,8 @@ export class HostState { this.lastLatency = null; this.status = "pending"; // 'online' | 'offline' | 'error' | 'pending' this.pinned = pinned; + // How many recorded checks in a row have failed, up to the last one. + this.consecutiveFailures = 0; } pushSample(timestamp, result) { @@ -281,6 +283,9 @@ export class HostState { if (result.error === "timeout") this.status = "error"; else if (result.error) this.status = "offline"; else this.status = "online"; + this.consecutiveFailures = result.error + ? this.consecutiveFailures + 1 + : 0; } pushPaused(timestamp) { @@ -534,7 +539,13 @@ class Reporter { // Checks one target. The check times out after CONFIG.requestTimeout; the // caller can give it up sooner through the optional signal, which also ends -// it as a timeout. +// it as a timeout. A failed check's reason says what went wrong and after +// how long; a check that answered has none. +// +// The URL is fetched as written, with nothing added to it: the Hetzner +// speed-test servers close the connection without an answer when the URL +// has a query string, and cache: "no-store" keeps the browser's cache out +// of the measurement. export async function measureLatency(url, signal) { const controller = new AbortController(); const timeoutId = setTimeout( @@ -543,13 +554,10 @@ export async function measureLatency(url, signal) { ); signal?.addEventListener("abort", () => controller.abort()); - const targetUrl = new URL(url); - targetUrl.searchParams.set("_cb", Date.now().toString()); - const start = performance.now(); try { - await fetch(targetUrl.toString(), { + await fetch(url, { method: "GET", mode: "no-cors", cache: "no-store", @@ -558,18 +566,28 @@ export async function measureLatency(url, signal) { const latency = Math.round(performance.now() - start); clearTimeout(timeoutId); if (latency > CONFIG.maxLatency) { - log.error(`${url} timeout (${latency}ms > ${CONFIG.maxLatency}ms)`); - return { latency: null, error: "timeout" }; + return { + latency: null, + error: "timeout", + reason: `answered after ${latency} ms, over the ${CONFIG.maxLatency} ms limit`, + }; } - return { latency, error: null }; + return { latency, error: null, reason: null }; } catch (err) { + const took = Math.round(performance.now() - start); clearTimeout(timeoutId); if (err.name === "AbortError") { - log.error(`${url} timeout (aborted)`); - return { latency: null, error: "timeout" }; + return { + latency: null, + error: "timeout", + reason: `timed out after ${took} ms (limit ${CONFIG.requestTimeout} ms)`, + }; } - log.error(`${url} unreachable`); - return { latency: null, error: "unreachable" }; + return { + latency: null, + error: "unreachable", + reason: `network error (${err.name}: ${err.message}) after ${took} ms`, + }; } } @@ -1136,6 +1154,26 @@ function sortAndRebuildWAN(state) { // --- Main Loop --------------------------------------------------------------- +// Writes one line to the browser console, and the same line to the debug +// log, for a check the page is about to record: for every check that +// failed, and for a check that answered after checks that failed. Called +// before host.pushSample, while host.consecutiveFailures still counts the +// checks before this one. +function logCheck(host, result) { + const target = `${host.name} ${host.url} at ${new Date().toISOString()}`; + const failed = host.consecutiveFailures; + if (result.error) { + const line = `netwatch: check failed: ${target}: ${result.reason}`; + console.error(line); + log.error(line); + } else if (failed > 0) { + const checks = failed === 1 ? "check" : "checks"; + const line = `netwatch: target recovered: ${target}: answered after ${result.latency} ms, following ${failed} failed ${checks} in a row`; + console.info(line); + log.info(line); + } +} + export async function tick(state, signal, onOffline) { const ts = Date.now(); @@ -1169,6 +1207,7 @@ export async function tick(state, signal, onOffline) { if (state.paused || signal.aborted || state.tickCount === 0) { return; } + logCheck(host, r); host.pushSample(ts, r); updateHostRow(host, state.allHosts.indexOf(host)); log.debug(`${host.name}: ${r.error ? r.error : r.latency + "ms"}`); diff --git a/test/unit/main.test.js b/test/unit/main.test.js index 0b037ab..d47bafe 100644 --- a/test/unit/main.test.js +++ b/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 < > " & and ' in a row's markup as // < > " & and '. test(`a target whose name and URL hold < > " & and ' shows those characters in its row`, () => {