authorgravatar for git@paperclover.netclover caruso <git@paperclover.net> 2026-03-28 18:06:21-07:00
committergravatar for git@paperclover.netclover caruso <git@paperclover.net> 2026-03-28 18:40:15-07:00
loga112bed705720e1c883d0c2a13e9175164544525
tree98927b5b4c0a87b202bd84c11b0bcbf2a38162cc
parente14fa6bdce7e5ab857860af2962d89e2ed9a92f4
signature Signed by SSH key SHA256:xbd+BjjhyBfwk7GVoURf9Yx0gzDerHbvYv7SddNWmAs

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

3 files changed, 86 insertions(+), 29 deletions(-)

lib/log.test.ts+44-2
...@@ -493,8 +493,9 @@ describe("log widgets", () => {...@@ -493,8 +493,9 @@ describe("log widgets", () => {
493493
494 host.writeOutput("log line;");494 host.writeOutput("log line;");
495495
496 let flag = true;
496 using _ = host.startWidget({497 using _ = host.startWidget({
497 format: ({ now }) => now > 500 ? null : `widget line one ${now}\nwidget line two`,498 format: ({ now }) => flag ? `widget line one ${now}\nwidget line two` : null,
498 fps: 1,499 fps: 1,
499 });500 });
500501
...@@ -506,8 +507,10 @@ describe("log widgets", () => {...@@ -506,8 +507,10 @@ describe("log widgets", () => {
506 "widget line one 0\nwidget line two\n",507 "widget line one 0\nwidget line two\n",
507 ]),508 ]),
508 });509 });
510 host.expectWithoutConsume(1000);
509 host.writeOutput(" rest of line\n");511 host.writeOutput(" rest of line\n");
510 host.expectFrame(1000, {512 flag = false;
513 host.expectFrame(0, {
511 stdout: " rest of line\n",514 stdout: " rest of line\n",
512 merged: testing.MockScreen.sync([515 merged: testing.MockScreen.sync([
513 ansi.cursorUp(1),516 ansi.cursorUp(1),
...@@ -519,6 +522,45 @@ describe("log widgets", () => {...@@ -519,6 +522,45 @@ describe("log widgets", () => {
519 ]),522 ]),
520 });523 });
521 host.cancel();524 host.cancel();
525 _?.stop();
526 });
527
528 test("writing during a render function is OK", () => {
529 const host = new testing.MockScreen();
530
531 using w = host.startWidget({
532 format: ({ now }) => {
533 host.writeOutput("log line\n");
534 return "widget line";
535 },
536 fps: 1,
537 });
538
539 host.expectFrame(0, {
540 stdout: "log line\n",
541 merged: testing.MockScreen.sync([
542 "log line\n",
543 "widget line\n",
544 ]),
545 });
546 host.expectFrame(1000, {
547 stdout: "log line\n",
548 merged: testing.MockScreen.sync([
549 ansi.cursorUp(1),
550 ansi.clearFullLine,
551 "log line\n",
552 "widget line\n",
553 ]),
554 });
555 w?.stop();
556 host.expectFrame(0, {
557 // stdout: "log line\n",
558 merged: testing.MockScreen.sync([
559 ansi.cursorUp(1),
560 ansi.clearFullLine,
561 ]),
562 });
563 host.cancel();
522 });564 });
523});565});
524566
lib/log.ts+28-11
...@@ -434,10 +434,11 @@ interface WidgetState {...@@ -434,10 +434,11 @@ interface WidgetState {
434export function createTerminalWidgetHost(434export function createTerminalWidgetHost(
435 env: TerminalWidgetHostOptions,435 env: TerminalWidgetHostOptions,
436): WidgetHost {436): WidgetHost {
437 const { lockTerminal, now, delay, writeOutputTemporaryLock } = env;437 const { lockTerminal, now, delay, writeOutputTemporaryLock, color } = env;
438438
439 let timer: async.Cancelable<void> | null = null;439 let timer: async.Cancelable<void> | null = null;
440440
441 let rendering = false;
441 let locks = 0;442 let locks = 0;
442 let redrawTime = 0;443 let redrawTime = 0;
443 let lastFlush = 0;444 let lastFlush = 0;
...@@ -454,6 +455,8 @@ export function createTerminalWidgetHost(...@@ -454,6 +455,8 @@ export function createTerminalWidgetHost(
454455
455 function redrawCallback() {456 function redrawCallback() {
456 timer = null;457 timer = null;
458 ASSERT(!rendering);
459 rendering = true;
457 redrawTime = (lastFlush = now()) - 0.00001; // windows time precision workaround460 redrawTime = (lastFlush = now()) - 0.00001; // windows time precision workaround
458461
459 // trivial path when not using widgets462 // trivial path when not using widgets
...@@ -479,6 +482,7 @@ export function createTerminalWidgetHost(...@@ -479,6 +482,7 @@ export function createTerminalWidgetHost(
479 }482 }
480 partialLineIndex = partialLineLength(buffer);483 partialLineIndex = partialLineLength(buffer);
481 buffer = "";484 buffer = "";
485 rendering = false
482 return;486 return;
483 }487 }
484488
...@@ -488,11 +492,17 @@ export function createTerminalWidgetHost(...@@ -488,11 +492,17 @@ export function createTerminalWidgetHost(
488 let newWidgetLines: string[] = [];492 let newWidgetLines: string[] = [];
489 let next = Infinity;493 let next = Infinity;
490 for (let w = 0, { length } = widgets; w < length; w += 1) {494 for (let w = 0, { length } = widgets; w < length; w += 1) {
491 const out = UNWRAP(widgets[w]).format({495 const widget = UNWRAP(widgets[w]);
492 now: lastFlush,496 let out: string | { text: string } | null;
493 width: columns,497 try {
494 height: rows,498 out = widget.format({
495 });499 now: lastFlush,
500 width: columns,
501 height: rows,
502 });
503 } catch (e) {
504 out = e instanceof Error ? stack.format(e, color) : errors.message(e);
505 }
496 if (!out) {506 if (!out) {
497 widgets.splice(w, 1);507 widgets.splice(w, 1);
498 UNWRAP(internals.splice(w, 1)[0]);508 UNWRAP(internals.splice(w, 1)[0]);
...@@ -513,6 +523,8 @@ export function createTerminalWidgetHost(...@@ -513,6 +523,8 @@ export function createTerminalWidgetHost(
513 newWidgetLines = newWidgetLines.slice(0, rows - 1);523 newWidgetLines = newWidgetLines.slice(0, rows - 1);
514 if (next < Infinity) redrawSoon(next);524 if (next < Infinity) redrawSoon(next);
515525
526 terminal ??= lockTerminal();
527
516 if (!newWidgetLines[0]) {528 if (!newWidgetLines[0]) {
517 ASSERT(!needsToSaveCursor);529 ASSERT(!needsToSaveCursor);
518 if (lines.length > 0) {530 if (lines.length > 0) {
...@@ -532,6 +544,7 @@ export function createTerminalWidgetHost(...@@ -532,6 +544,7 @@ export function createTerminalWidgetHost(
532 if (buffer) terminal.writeOutput(buffer);544 if (buffer) terminal.writeOutput(buffer);
533 buffer = "";545 buffer = "";
534 if (hasSyncStart) terminal.writeInteractive(ansi.syncEnd);546 if (hasSyncStart) terminal.writeInteractive(ansi.syncEnd);
547 rendering = false;
535 return;548 return;
536 }549 }
537550
...@@ -631,19 +644,19 @@ export function createTerminalWidgetHost(...@@ -631,19 +644,19 @@ export function createTerminalWidgetHost(
631 needsToRestoreCursor ||= needsToSaveCursor;644 needsToRestoreCursor ||= needsToSaveCursor;
632 needsToSaveCursor = false;645 needsToSaveCursor = false;
633 lines = newWidgetLines;646 lines = newWidgetLines;
634
635 buffer = "";647 buffer = "";
648 rendering = false;
636 }649 }
637650
638 function redrawSoon(ms: number) {651 function redrawSoon(ms: number) {
639 if (locks > 0 || (ms === 0 && timer)) return;652 if (locks > 0 || (ms === 0 && rendering)) return;
640 const newRedrawTime = now() + ms;653 const newRedrawTime = now() + ms;
641 if (timer) {654 if (timer) {
642 if (redrawTime < newRedrawTime) return;655 if (redrawTime < newRedrawTime) return;
643 timer.cancel(); // cancel previous656 timer.cancel(); // cancel previous
644 timer = null;
645 }657 }
646 redrawTime = newRedrawTime + 1;658 // 1ms wiggle room, generally runtimes have much larger variance on timers
659 redrawTime = newRedrawTime - 1;
647 timer = delay(ms);660 timer = delay(ms);
648 timer.then(redrawCallback);661 timer.then(redrawCallback);
649 }662 }
...@@ -690,6 +703,7 @@ export function createTerminalWidgetHost(...@@ -690,6 +703,7 @@ export function createTerminalWidgetHost(
690 if (chunk) buffer += chunk, redrawSoon(0);703 if (chunk) buffer += chunk, redrawSoon(0);
691 },704 },
692 getDrawLock(mode) {705 getDrawLock(mode) {
706 if (rendering) ASSERT(locks === 0);
693 if (locks === 0) {707 if (locks === 0) {
694 flushAndClear(mode === "short");708 flushAndClear(mode === "short");
695 if (widgets.length > 0 && terminal) {709 if (widgets.length > 0 && terminal) {
...@@ -756,12 +770,14 @@ export function createTerminalWidgetHost(...@@ -756,12 +770,14 @@ export function createTerminalWidgetHost(
756 };770 };
757 },771 },
758 cancel() {772 cancel() {
773 ASSERT(!rendering, "cannot call cancel() during rendering");
759 flushAndClear(false);774 flushAndClear(false);
760 widgets.splice(0, widgets.length);775 widgets.splice(0, widgets.length);
776 internals.splice(0, internals.length);
761 },777 },
762 delay,778 delay,
763 now,779 now,
764 capabilities: env.color ? ["widget", "color"] : ["widget"],780 capabilities: color ? ["widget", "color"] : ["widget"],
765 };781 };
766}782}
767783
...@@ -1200,6 +1216,7 @@ export type MessageFormatFunction = (...@@ -1200,6 +1216,7 @@ export type MessageFormatFunction = (
1200) => string;1216) => string;
12011217
1202import { ASSERT, UNWRAP } from "./assert.ts";1218import { ASSERT, UNWRAP } from "./assert.ts";
1219import * as errors from "./error.ts";
1203import * as async from "./async.ts";1220import * as async from "./async.ts";
1204import * as stack from "./log/stack.ts";1221import * as stack from "./log/stack.ts";
1205import * as node from "./node.ts";1222import * as node from "./node.ts";
lib/testing.ts+14-16
...@@ -116,7 +116,6 @@ export class FakeTimers {...@@ -116,7 +116,6 @@ export class FakeTimers {
116 resolve: () => void;116 resolve: () => void;
117 src: stack.Frame[];117 src: stack.Frame[];
118 }> = [];118 }> = [];
119 waitTime = 0;
120119
121 now: () => number = () => {120 now: () => number = () => {
122 return this.time;121 return this.time;
...@@ -127,11 +126,10 @@ export class FakeTimers {...@@ -127,11 +126,10 @@ export class FakeTimers {
127 new SyncPromise((resolve) => {126 new SyncPromise((resolve) => {
128 ASSERT(this.entries.length === 0);127 ASSERT(this.entries.length === 0);
129 this.entries.push({128 this.entries.push({
130 duration: ms - this.waitTime,129 duration: ms,
131 resolve,130 resolve,
132 src,131 src,
133 });132 });
134 this.waitTime = ms;
135 }),133 }),
136 () => {134 () => {
137 ASSERT(this.entries.length === 1);135 ASSERT(this.entries.length === 1);
...@@ -245,7 +243,17 @@ export class MockScreen implements Disposable, log.WidgetHost {...@@ -245,7 +243,17 @@ export class MockScreen implements Disposable, log.WidgetHost {
245 }243 }
246244
247 expectWithoutConsume(ms: number) {245 expectWithoutConsume(ms: number) {
248 ASSERT(UNWRAP(this.timers.entries[0]).duration === 0);246 const wait = UNWRAP(
247 this.timers.entries[0],
248 () => this.out.length > 0 ? "terminal i/o did not wait" : "no terminal i/o",
249 );
250 ASSERT(
251 ms === wait.duration,
252 `expected ${ms}ms to pass, got ${wait.duration}, from:\n${
253 wait.src.map((frame) => stack.formatFrame(frame, true)).join("\n")
254 }`,
255 );
256 return wait;
249 }257 }
250258
251 expectFrame(ms: number | null, { stdout, stderr, merged: out }: {259 expectFrame(ms: number | null, { stdout, stderr, merged: out }: {
...@@ -254,19 +262,9 @@ export class MockScreen implements Disposable, log.WidgetHost {...@@ -254,19 +262,9 @@ export class MockScreen implements Disposable, log.WidgetHost {
254 merged?: string;262 merged?: string;
255 }) {263 }) {
256 if (ms != null) {264 if (ms != null) {
257 const wait = UNWRAP(265 const wait = this.expectWithoutConsume(ms);
258 this.timers.entries.shift(),266 this.timers.entries.shift();
259 () => this.out.length > 0 ? "terminal i/o did not wait" : "no terminal i/o",
260 );
261 ASSERT(
262 ms === wait.duration,
263 `expected ${ms}ms to pass, got ${wait.duration}, from:\n${
264 wait.src.map((frame) => stack.formatFrame(frame, true)).join("\n")
265 }`,
266 );
267
268 this.timers.time += wait.duration;267 this.timers.time += wait.duration;
269 this.timers.waitTime = 0;
270 wait.resolve();268 wait.resolve();
271 } else {269 } else {
272 ASSERT(this.timers.entries.length === 0);270 ASSERT(this.timers.entries.length === 0);