Debug log adds each line instead of drawing the whole panel (closes #131)

With the debug log open, every line written drew the panel again with up to 1000 lines, and a check that ends while the page draws is timed only when the drawing is done, so latencies measured with the panel open read too high. Each line is now appended to the open panel and its first line dropped once it holds more than maxLogEntries; the whole panel is drawn only when it is opened. Scrolling to the newest line reads the panel's height, which lays out all its lines, so it runs once a frame, with at most one frame request waiting. Model: opus-5-5
2026-10-14 10:04:25 +00:00
parent b1eefe0c29
commit 94c0556671
3 changed files with 96 additions and 24 deletions
@@ -22,6 +22,15 @@ Decide whether the repo moves to the layout `REPO_POLICIES.md` gives, with

 # Completed Steps

+- 2026-10-14: opening the debug log no longer raises the measured latencies
+  ([#131](https://git.eeqj.de/sneak/netwatch/issues/131)). With the panel open,
+  each line written drew the panel again with every line before it, up to 1000,
+  and a check that ends while the page draws is timed only when the drawing is
+  done. Each line is now added at the end of the open panel, its first line is
+  dropped once it holds more than 1000, and it scrolls to its newest line once a
+  frame rather than once a line; the whole panel is drawn only when it is
+  opened. A unit test writes more lines than the panel keeps and checks that the
+  lines already shown are left as they are
 - 2026-10-07: the files shared from `sneak/prompts` are its copies at commit
  `dd4027b` ([#113](https://git.eeqj.de/sneak/netwatch/issues/113)), with this
  repository's own entries after the shared content in `.gitignore`,
@@ -144,13 +144,15 @@ const WAN_HOSTS = [

 const debugLog = [];

-const log = (() => {
+export const log = (() => {
    function append(level, message) {
-        debugLog.push({ timestamp: new Date(), level, message });
+        const entry = { timestamp: new Date(), level, message };
+        debugLog.push(entry);
        if (debugLog.length > CONFIG.maxLogEntries)
            debugLog.splice(0, debugLog.length - CONFIG.maxLogEntries);
        const panel = document.getElementById("debug-panel");
-        if (panel && !panel.classList.contains("hidden")) renderDebugLog();
+        if (panel && !panel.classList.contains("hidden"))
+            appendDebugLogLine(entry);
    }
    return {
        error: (msg) => append("error", msg),
@@ -1079,9 +1081,8 @@ function updateHealthBox(state) {

 // --- Debug Log Renderer ------------------------------------------------------

-function renderDebugLog() {
-    const el = document.getElementById("debug-log");
-    if (!el) return;
+// One line of the debug log panel, its message set as text.
+function debugLogLine(entry) {
    const levelColors = {
        error: "text-red-400",
        warning: "text-orange-400",
@@ -1089,19 +1090,43 @@ function renderDebugLog() {
        info: "text-gray-300",
        debug: "text-gray-500",
    };
-    el.replaceChildren(
-        ...debugLog.map((entry) => {
-            const ts = formatUTCTimestamp(entry.timestamp);
-            const lvl = entry.level.toUpperCase().padEnd(7);
-            const line = document.createElement("div");
-            line.className = levelColors[entry.level] || "text-gray-400";
-            line.textContent = `${ts} ${lvl} ${entry.message}`;
-            return line;
-        }),
-    );
+    const ts = formatUTCTimestamp(entry.timestamp);
+    const lvl = entry.level.toUpperCase().padEnd(7);
+    const line = document.createElement("div");
+    line.className = levelColors[entry.level] || "text-gray-400";
+    line.textContent = `${ts} ${lvl} ${entry.message}`;
+    return line;
+}
+
+// Draws every line of the debug log into the panel, when it is opened.
+function renderDebugLog() {
+    const el = document.getElementById("debug-log");
+    if (!el) return;
+    el.replaceChildren(...debugLog.map((entry) => debugLogLine(entry)));
    el.scrollTop = el.scrollHeight;
 }

+// The request that scrolls the open panel to its newest line in the next
+// frame. One waits at most, also in a hidden tab, where frames do not run.
+let debugLogScrollFrame = 0;
+
+// Adds entry to the open panel as its last line, and drops the first line
+// once the panel holds more than maxLogEntries. A check that ends while the
+// page is busy is timed only when the page is done, so the lines already
+// shown are left as they are, and the panel is scrolled once a frame
+// rather than once a line: scrolling it lays out all of its lines again.
+function appendDebugLogLine(entry) {
+    const el = document.getElementById("debug-log");
+    if (!el) return;
+    el.append(debugLogLine(entry));
+    if (el.children.length > CONFIG.maxLogEntries)
+        el.removeChild(el.firstElementChild);
+    cancelAnimationFrame(debugLogScrollFrame);
+    debugLogScrollFrame = requestAnimationFrame(() => {
+        el.scrollTop = el.scrollHeight;
+    });
+}
+
 // --- Sorting -----------------------------------------------------------------

 // Sort WAN hosts: pinned hosts first (alphabetically), then unpinned hosts
@@ -13,19 +13,21 @@ import {
    humanDuration,
    latencyClass,
    latencyHex,
+    log,
    measureLatency,
    tick,
 } from "../../src/main.js";

 // There is no page here, so the tests stand in for it. The debug log looks
-// for its panel by id and finds none. Each element of a host's row that
-// tick or greyOutUI draws into is a plain object, made the first time a
-// 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. In
-// each test, console.error and console.info print nothing and keep what
-// they are given.
+// for its panel by id and finds none, an element the page creates is a
+// plain object, and no frame the page asks for ever comes. Each element of
+// a host's row that tick or greyOutUI draws into is a plain object, made
+// the first time a 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. In each test, console.error and console.info
+// print nothing and keep what they are given.
 const doNothing = () => {};
 let elements;
 beforeEach((t) => {
@@ -45,8 +47,11 @@ const canvasContext = {
    arc: doNothing,
 };
 globalThis.window = {};
+globalThis.requestAnimationFrame = doNothing;
+globalThis.cancelAnimationFrame = doNothing;
 globalThis.document = {
    getElementById: () => null,
+    createElement: () => ({}),
    querySelector: (selector) =>
        (elements[selector] ??= {
            getContext: () => canvasContext,
@@ -378,6 +383,39 @@ test("a check that fails in the first round, which is discarded, writes nothing
    assert.deepEqual(consoleLines("info"), []);
 });

+// panel stands in for the open debug log panel, and for the element in it
+// that holds its lines, whichever the page looks up by id; the lines are
+// kept in order in lines. Drawing the whole panel, as opening it does,
+// replaces every line with a new one.
+test("with the debug log open, writing more lines than it keeps adds each to the panel and leaves the lines already shown as they are", (t) => {
+    const lines = [];
+    const panel = {
+        classList: { contains: () => false },
+        children: lines,
+        get firstElementChild() {
+            return lines[0];
+        },
+        append: (line) => lines.push(line),
+        removeChild: (line) => lines.splice(lines.indexOf(line), 1),
+        replaceChildren: (...newLines) =>
+            lines.splice(0, lines.length, ...newLines),
+    };
+    t.mock.method(document, "getElementById", () => panel);
+    const kept = CONFIG.maxLogEntries;
+
+    for (let i = 1; i <= kept; i++) log.info(`line ${i}`);
+    const shown = [...lines];
+    for (let i = kept + 1; i <= kept + 5; i++) log.info(`line ${i}`);
+
+    assert.deepEqual(
+        lines.map((line) => line.textContent.match(/line \d+$/)?.[0]),
+        Array.from({ length: kept }, (_, i) => `line ${i + 6}`),
+    );
+    // The first five lines shown were dropped, and the rest are the same
+    // lines, not drawn again.
+    shown.slice(5).forEach((line, i) => assert.equal(lines[i], line));
+});
+
 // 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`, () => {