From a112bed705720e1c883d0c2a13e9175164544525 Mon Sep 17 00:00:00 2001 From: clover caruso Date: Sat, 28 Mar 2026 18:06:21 -0700 Subject: [PATCH] fix(lib/log): timer fixes + write/getDrawLock inside of formatter thankfully, the widget formatters are called before most rendering state is needed, but it brings up some reasonable edge cases which are now handled better. as a result, the timers when having widgets of differing fps are more accurate, particularly around starting and stopping them. resolves #102 --- lib/log.test.ts | 46 ++++++++++++++++++++++++++++++++++++++++++++-- lib/log.ts | 39 ++++++++++++++++++++++++++++----------- lib/testing.ts | 30 ++++++++++++++---------------- 3 files changed, 86 insertions(+), 29 deletions(-) diff --git a/lib/log.test.ts b/lib/log.test.ts index d74fce0a35585a0673d470953001fda02c74c823..335ef1b5333addb27e6e39582cda2803a67b30df 100644 --- a/lib/log.test.ts +++ b/lib/log.test.ts @@ -493,8 +493,9 @@ describe("log widgets", () => { host.writeOutput("log line;"); + let flag = true; using _ = host.startWidget({ - format: ({ now }) => now > 500 ? null : `widget line one ${now}\nwidget line two`, + format: ({ now }) => flag ? `widget line one ${now}\nwidget line two` : null, fps: 1, }); @@ -506,8 +507,10 @@ describe("log widgets", () => { "widget line one 0\nwidget line two\n", ]), }); + host.expectWithoutConsume(1000); host.writeOutput(" rest of line\n"); - host.expectFrame(1000, { + flag = false; + host.expectFrame(0, { stdout: " rest of line\n", merged: testing.MockScreen.sync([ ansi.cursorUp(1), @@ -519,6 +522,45 @@ describe("log widgets", () => { ]), }); host.cancel(); + _?.stop(); + }); + + test("writing during a render function is OK", () => { + const host = new testing.MockScreen(); + + using w = host.startWidget({ + format: ({ now }) => { + host.writeOutput("log line\n"); + return "widget line"; + }, + fps: 1, + }); + + host.expectFrame(0, { + stdout: "log line\n", + merged: testing.MockScreen.sync([ + "log line\n", + "widget line\n", + ]), + }); + host.expectFrame(1000, { + stdout: "log line\n", + merged: testing.MockScreen.sync([ + ansi.cursorUp(1), + ansi.clearFullLine, + "log line\n", + "widget line\n", + ]), + }); + w?.stop(); + host.expectFrame(0, { + // stdout: "log line\n", + merged: testing.MockScreen.sync([ + ansi.cursorUp(1), + ansi.clearFullLine, + ]), + }); + host.cancel(); }); }); diff --git a/lib/log.ts b/lib/log.ts index 70201bd2fd7fd70333ec1c86330d5ff03f2d1df6..881fb158655280db90fb2cf2b4ca79500af69e99 100644 --- a/lib/log.ts +++ b/lib/log.ts @@ -434,10 +434,11 @@ interface WidgetState { export function createTerminalWidgetHost( env: TerminalWidgetHostOptions, ): WidgetHost { - const { lockTerminal, now, delay, writeOutputTemporaryLock } = env; + const { lockTerminal, now, delay, writeOutputTemporaryLock, color } = env; let timer: async.Cancelable | null = null; + let rendering = false; let locks = 0; let redrawTime = 0; let lastFlush = 0; @@ -454,6 +455,8 @@ export function createTerminalWidgetHost( function redrawCallback() { timer = null; + ASSERT(!rendering); + rendering = true; redrawTime = (lastFlush = now()) - 0.00001; // windows time precision workaround // trivial path when not using widgets @@ -479,6 +482,7 @@ export function createTerminalWidgetHost( } partialLineIndex = partialLineLength(buffer); buffer = ""; + rendering = false return; } @@ -488,11 +492,17 @@ export function createTerminalWidgetHost( let newWidgetLines: string[] = []; let next = Infinity; for (let w = 0, { length } = widgets; w < length; w += 1) { - const out = UNWRAP(widgets[w]).format({ - now: lastFlush, - width: columns, - height: rows, - }); + const widget = UNWRAP(widgets[w]); + let out: string | { text: string } | null; + try { + out = widget.format({ + now: lastFlush, + width: columns, + height: rows, + }); + } catch (e) { + out = e instanceof Error ? stack.format(e, color) : errors.message(e); + } if (!out) { widgets.splice(w, 1); UNWRAP(internals.splice(w, 1)[0]); @@ -513,6 +523,8 @@ export function createTerminalWidgetHost( newWidgetLines = newWidgetLines.slice(0, rows - 1); if (next < Infinity) redrawSoon(next); + terminal ??= lockTerminal(); + if (!newWidgetLines[0]) { ASSERT(!needsToSaveCursor); if (lines.length > 0) { @@ -532,6 +544,7 @@ export function createTerminalWidgetHost( if (buffer) terminal.writeOutput(buffer); buffer = ""; if (hasSyncStart) terminal.writeInteractive(ansi.syncEnd); + rendering = false; return; } @@ -631,19 +644,19 @@ export function createTerminalWidgetHost( needsToRestoreCursor ||= needsToSaveCursor; needsToSaveCursor = false; lines = newWidgetLines; - buffer = ""; + rendering = false; } function redrawSoon(ms: number) { - if (locks > 0 || (ms === 0 && timer)) return; + if (locks > 0 || (ms === 0 && rendering)) return; const newRedrawTime = now() + ms; if (timer) { if (redrawTime < newRedrawTime) return; timer.cancel(); // cancel previous - timer = null; } - redrawTime = newRedrawTime + 1; + // 1ms wiggle room, generally runtimes have much larger variance on timers + redrawTime = newRedrawTime - 1; timer = delay(ms); timer.then(redrawCallback); } @@ -690,6 +703,7 @@ export function createTerminalWidgetHost( if (chunk) buffer += chunk, redrawSoon(0); }, getDrawLock(mode) { + if (rendering) ASSERT(locks === 0); if (locks === 0) { flushAndClear(mode === "short"); if (widgets.length > 0 && terminal) { @@ -756,12 +770,14 @@ export function createTerminalWidgetHost( }; }, cancel() { + ASSERT(!rendering, "cannot call cancel() during rendering"); flushAndClear(false); widgets.splice(0, widgets.length); + internals.splice(0, internals.length); }, delay, now, - capabilities: env.color ? ["widget", "color"] : ["widget"], + capabilities: color ? ["widget", "color"] : ["widget"], }; } @@ -1200,6 +1216,7 @@ export type MessageFormatFunction = ( ) => string; import { ASSERT, UNWRAP } from "./assert.ts"; +import * as errors from "./error.ts"; import * as async from "./async.ts"; import * as stack from "./log/stack.ts"; import * as node from "./node.ts"; diff --git a/lib/testing.ts b/lib/testing.ts index 8fb4fde0095bcc5966c42140786b600f66953d8b..5348c1dbe74693db830dffe0532e2ec0203bb046 100644 --- a/lib/testing.ts +++ b/lib/testing.ts @@ -116,7 +116,6 @@ export class FakeTimers { resolve: () => void; src: stack.Frame[]; }> = []; - waitTime = 0; now: () => number = () => { return this.time; @@ -127,11 +126,10 @@ export class FakeTimers { new SyncPromise((resolve) => { ASSERT(this.entries.length === 0); this.entries.push({ - duration: ms - this.waitTime, + duration: ms, resolve, src, }); - this.waitTime = ms; }), () => { ASSERT(this.entries.length === 1); @@ -245,7 +243,17 @@ export class MockScreen implements Disposable, log.WidgetHost { } expectWithoutConsume(ms: number) { - ASSERT(UNWRAP(this.timers.entries[0]).duration === 0); + const wait = UNWRAP( + this.timers.entries[0], + () => this.out.length > 0 ? "terminal i/o did not wait" : "no terminal i/o", + ); + ASSERT( + ms === wait.duration, + `expected ${ms}ms to pass, got ${wait.duration}, from:\n${ + wait.src.map((frame) => stack.formatFrame(frame, true)).join("\n") + }`, + ); + return wait; } expectFrame(ms: number | null, { stdout, stderr, merged: out }: { @@ -254,19 +262,9 @@ export class MockScreen implements Disposable, log.WidgetHost { merged?: string; }) { if (ms != null) { - const wait = UNWRAP( - this.timers.entries.shift(), - () => this.out.length > 0 ? "terminal i/o did not wait" : "no terminal i/o", - ); - ASSERT( - ms === wait.duration, - `expected ${ms}ms to pass, got ${wait.duration}, from:\n${ - wait.src.map((frame) => stack.formatFrame(frame, true)).join("\n") - }`, - ); - + const wait = this.expectWithoutConsume(ms); + this.timers.entries.shift(); this.timers.time += wait.duration; - this.timers.waitTime = 0; wait.resolve(); } else { ASSERT(this.timers.entries.length === 0); -- 2.54.0