From 76e57112a9715234e63ea77458888e56836e6286 Mon Sep 17 00:00:00 2001 From: clover caruso Date: Mon, 12 Jan 2026 21:50:39 -0800 Subject: [PATCH] feat(lib/log): messages without newlines + terminal lock resolves #70 by renaming `writeLine` to `write`, which also meant reworking the message interface to support messages that do not end in a newline. this is a critical oversight that progress library needs. now, the global log or a progress nodes support this, which is great for unstructured data streams. additionally, the way the widget host works has been drastically altered, it works off of a terminal lock. this implements the vision in #65. in the future, i'll make it so interweaving scopes can display cleanly. --- lib/log.test.ts | 292 +++++++++++++++++++++++++-- lib/log.ts | 469 +++++++++++++++++++++++++++++-------------- lib/node.ts | 8 + lib/progress.test.ts | 16 +- lib/progress.ts | 11 +- lib/testing.ts | 137 +++++++------ 6 files changed, 695 insertions(+), 238 deletions(-) diff --git a/lib/log.test.ts b/lib/log.test.ts index a525e7a72a4eecda2759256e3e8e05bc09e98a10..cead4dd4a06c00111b93f1c92e35e9d5b6e21cb4 100644 --- a/lib/log.test.ts +++ b/lib/log.test.ts @@ -5,21 +5,135 @@ log satisfies log.Scope; // implementation that buffers all bytes in memory. it is a great // example of how modular the entire system is. describe("log widgets", () => { - test("writeLine buffers", () => { - using host = new testing.MockScreen(); - host.writeLine("hello world"); - host.writeLine("and so on"); + test("write buffering", () => { + const host = new testing.MockScreen(); + host.write("hello world "); + host.write("and so on\n"); host.expectFrame(0, { - stdout: "hello world\nand so on\n", + stdout: "hello world and so on\n", }); - host.writeLine("more logs"); + host.write("more logs\n"); host.expectFrame(0, { stdout: "more logs\n", }); + host.write("abc def"); + { + const unlock = host.getDrawLock(); + host.expectFrame(null, { + stdout: "abc def", + }); + unlock(); + } + host.expectFrame(null, { stdout: "" }); + { + const unlock = host.getDrawLock(); + host.write("abc def "); + host.write("hijk"); + unlock(); + host.expectFrame(0, { + stdout: "abc def hijk", + }); + } + host.expectFrame(null, { stdout: "" }); + host.cancel(); + }); + + test("widget partial line", () => { + const host = new testing.MockScreen(); + const wd1: log.Widget = { format: (now) => `t=${now}` }; + const w1 = host.startWidget(wd1); + host.expectFrame(0, { + stderr: testing.MockScreen.sync([ + "t=0\n", + ]), + }); + host.expectNone(); + host.write("partial line"); + host.expectFrame(0, { + merged: testing.MockScreen.sync([ + ansi.cursorUp(1), + ansi.clearFullLine, + "partial line", + ansi.cursorSave, + "\n", + "t=0\n", + ]), + stdout: "partial line", + stderr: testing.MockScreen.sync([ + ansi.cursorUp(1), + ansi.clearFullLine, + ansi.cursorSave, + "\n", + "t=0\n", + ]), + }); + host.write(" and more\n"); + host.expectFrame(0, { + merged: testing.MockScreen.sync([ + ansi.cursorRestore, + " and more\n", + "t=0\n", + ]), + stdout: " and more\n", + stderr: testing.MockScreen.sync([ + ansi.cursorRestore, + "t=0\n", + ]), + }); + host.cancel(); + }); + + test("widget partial line 2", () => { + const host = new testing.MockScreen(); + const wd1: log.Widget = { format: (now) => `abc\ndefg` }; + const w1 = host.startWidget(wd1); + host.expectFrame(0, { + stderr: testing.MockScreen.sync([ + "abc\ndefg\n", + ]), + }); + // abc + // defg + host.expectNone(); + host.write("partial line"); + // abc + // defg + // [c] + host.expectFrame(0, { + merged: testing.MockScreen.sync([ + ansi.cursorUp(2), + ansi.clearFullLine, + "partial line", + ansi.cursorSave + "\n", + "abc", + ansi.clearToEndOfLine, + "\ndefg\n", + ]), + }); + host.write(" and more\na"); + // partial line[T] + // abc + // defg + // [CURSOR] + // move up 3, right 12 + host.expectFrame(0, { + merged: testing.MockScreen.sync([ + ansi.cursorUp(2), + ansi.clearFullLine, + ansi.cursorRestore, + " and more\n", + "a", + ansi.cursorSave + "\n", + "abc", + ansi.clearToEndOfLine, + "\ndefg\n", + ]), + }); + host.cancel(); }); test("widget with interweaving logs", () => { - using host = new testing.MockScreen(); + const host = new testing.MockScreen(); using _ = host.startWidget({ format: (now) => `line one ${now}\nline two`, @@ -27,15 +141,13 @@ describe("log widgets", () => { host.expectFrame(0, { stderr: testing.MockScreen.sync([ - ansi.startOfLine, "line one 0\nline two\n", ]), }); - host.writeLine("info: line of log"); + host.write("info: line of log\n"); host.expectFrame(0, { merged: testing.MockScreen.sync([ - ansi.startOfLine, ansi.cursorUp(2), ansi.clearFullLine, "info: line of log\n", @@ -43,11 +155,10 @@ describe("log widgets", () => { ]), }); - host.writeLine("warn: line of log"); - host.writeLine("error: line of log"); + host.write("warn: line of log\n"); + host.write("error: line of log\n"); host.expectFrame(0, { merged: testing.MockScreen.sync([ - ansi.startOfLine, ansi.cursorUp(1), ansi.clearFullLine, ansi.cursorUp(1), @@ -57,16 +168,112 @@ describe("log widgets", () => { "line one 0\nline two\n", ]), }); + host.cancel(); }); - test("widget with logs in same frame", () => { - using host = new testing.MockScreen(); + test("temporary drawing lock", () => { + const host = new testing.MockScreen(); - host.writeLine("log line 1"); - host.writeLine("log line 2"); + using _ = host.startWidget({ + format: (now) => `line one ${now}\nline two`, + }); + + host.expectFrame(0, { + stderr: testing.MockScreen.sync([ + "line one 0\nline two\n", + ]), + }); + + host.write("info: line of log\n"); + host.expectFrame(0, { + merged: testing.MockScreen.sync([ + ansi.cursorUp(2), + ansi.clearFullLine, + "info: line of log\n", + "line one 0\nline two\n", + ]), + }); + + { + host.write("warn: line of log\n"); + host.expectWithoutConsume(0); + const unlock = host.getDrawLock("short"); + // info: line of log + // line one 0 + // line two + // [C] + host.expectFrame(null, { + merged: [ + ansi.syncStart, + ansi.cursorUp(1), + ansi.clearFullLine, + ansi.cursorUp(1), + ansi.clearFullLine, + "warn: line of log\n", + ].join(""), + stdout: "warn: line of log\n", + }); + const unlock2 = host.getDrawLock("long"); + host.expectNone(); + host.write("error: line of log\n"); + host.expectNone(); + unlock2(); + host.expectNone(); + unlock(); + // warn: line of log + // [c] + host.expectFrame(0, { + merged: [ + "error: line of log\n", + "line one 0\nline two\n", + ansi.syncEnd, + ].join(""), + }); + host.cancel(); + } + { + const unlock = host.getDrawLock("short"); + // info: line of log + // line one 0 + // line two + // [C] + host.expectFrame(null, { + merged: [ + ansi.syncStart, + ansi.cursorUp(1), + ansi.clearFullLine, + ansi.cursorUp(1), + ansi.clearFullLine, + ].join(""), + stdout: "", + }); + const unlock2 = host.getDrawLock("long"); + host.expectNone(); + unlock2(); + host.expectNone(); + unlock(); + // warn: line of log + // [c] + host.expectFrame(0, { + merged: [ + "line one 0\nline two\n", + ansi.syncEnd, + ].join(""), + }); + host.cancel(); + } + }); + + test("widget expires", () => { + const host = new testing.MockScreen(); + + host.write("log line 1\n"); + host.write("log line 2\n"); using _ = host.startWidget({ - format: (now) => `widget line one ${now}\nwidget line two`, + format: (now) => + now > 1000 ? null : `widget line one ${now}\nwidget line two`, + fps: 1, }); host.expectFrame(0, { @@ -77,6 +284,55 @@ describe("log widgets", () => { "widget line one 0\nwidget line two\n", ]), }); + host.expectFrame(1000, { + merged: testing.MockScreen.sync([ + ansi.cursorUp(2), + "widget line one 1000\nwidget line two\n", + ]), + }); + host.expectFrame(1000, { + merged: testing.MockScreen.sync([ + ansi.cursorUp(1), + ansi.clearFullLine, + ansi.cursorUp(1), + ansi.clearFullLine, + ]), + }); + host.cancel(); + }); + + test("widget expires partial line output", () => { + const host = new testing.MockScreen(); + + host.write("log line;"); + + using _ = host.startWidget({ + format: (now) => + now > 500 ? null : `widget line one ${now}\nwidget line two`, + fps: 1, + }); + + host.expectFrame(0, { + stdout: "log line;", + merged: testing.MockScreen.sync([ + "log line;", + ansi.cursorSave + "\n", + "widget line one 0\nwidget line two\n", + ]), + }); + host.write(" rest of line\n"); + host.expectFrame(1000, { + stdout: " rest of line\n", + merged: testing.MockScreen.sync([ + ansi.cursorUp(1), + ansi.clearFullLine, + ansi.cursorUp(1), + ansi.clearFullLine, + ansi.cursorRestore, + " rest of line\n", + ]), + }); + host.cancel(); }); }); diff --git a/lib/log.ts b/lib/log.ts index b3c98536f6422365b42fa6ae6e95da1b5f2ad3ae..7b2d0104442dca0eb1dc71f6c3fbc5b0552a8179 100644 --- a/lib/log.ts +++ b/lib/log.ts @@ -1,9 +1,11 @@ /** * by using `lib/log.ts`, an application gets easy scoped logging as well as - * integration with terminal widgets such as `lib/progress.ts`. + * integration with terminal widgets such as `lib/progress.ts`. even when these + * widgets are active, using the logging interface is optional; global I/O with + * `console.*` and `process.std{out/err}` are patched to play nice. * * the pattern for using this module is to shadow the global `console` with a - * per-file logging scope: + * per-file logging scope, which makes it impossible to use the wrong logger. * * ```ts * import * as log from "@clo/lib/log"; @@ -21,17 +23,19 @@ * now, the code reads familiarly (`console.log` is universally understood), * but the output is organized into relevant scopes. * - * in addition to static log messages, a system for interactive I/O - * {@linkcode Widget} is provided by calling {@linkcode startWidget}. these - * allow showing temporary or interactive information, such as program status - * or input prompts. a powerful example of this system in action is - * `lib/progress.ts`, which uses a log widget by default to show status. + * in addition to static log messages, a system for interactive I/O via the + * {@linkcode Widget} interface can be started with {@linkcode startWidget}. + * these allow showing temporary or interactive information, such as program + * status or input prompts. a powerful example of this system in action is + * `lib/progress.ts`, which uses a widget as it's default rendering backend. * (TODO: widgets cannot recieve "input" data yet) * - * this module offers two environment integrations: + * `lib/log.ts` offers two environment integrations: * - in node.js, log messages are colored depending on the level and show - * widgets directly under the long using ANSI cursor controls. - * - otherwise, logs are surfaced using the global `console` API + * widgets directly under the long using ANSI cursor controls. when the + * terminal is not a TTY, widgets are silent. + * - in browsers and other, logs are surfaced using the global `console` API + * and widgets are disabled. * * custom log integrations can be built on top of this module by calling * `log.tee()` to duplicate all messages elsewhere. for example, a project may @@ -72,6 +76,11 @@ export interface Scope { tee(writer: (message: Message) => void): ts.Dispose; } +export interface RootScope extends Scope { + /** write a partial line to the output. */ + write(text: string): void; +} + export const originalLogArgs = Symbol("originalLogArgs"); export interface Message { level: "error" | "warn" | "info" | "debug"; @@ -85,6 +94,8 @@ export interface Message { stack?: stack.Frame[]; /** arbitrary data from the logging source. */ custom?: Partial>; + /** print a newline at the end of this log line? */ + newline?: boolean; /** * original logging arguments, if present. this field is indexed by a symbol * so that it is lost during JSON serialization, as callers are allowed to log @@ -140,6 +151,7 @@ export function replaceGlobalFormatFunction( globalMessageFormatFunction = format; } +/** includes the trailing newline for standard log messages */ export function formatMessage(msg: Message, colors: boolean): string { return globalMessageFormatFunction(msg, colors); } @@ -169,21 +181,23 @@ export function startWidget(widget: Widget): ts.Dispose { * no built-in prefix or formatting. ensures the text does not interweave. data * will be flushed in the next frame or when drawing is {@link getDrawLock|unlocked}. */ -export function writeLine(text: string) { - globalWidgetHost.writeLine(text); +export function write(text: string) { + globalWidgetHost.write(text); } -/** write a Message object directly. */ +/** write a {@linkcode Message} object directly. */ export function writeMessage(m: Message) { globalLog.writeMessage(m); } /** - * while locked, no widgets will draw. prefer `writeLine`. - * this lock is not exclusive. + * while locked, no widgets will draw. prefer calling `write` to opt into + * automatic buffering. this lock is not exclusive. if the lock will be held + * for an extremely short amount of time, pass `"short"` which will allow + * more optimized use of ansi synchronization codes. */ -export function getDrawLock(): ts.Dispose { - return globalWidgetHost.getDrawLock(); +export function getDrawLock(mode: "long" | "short"): ts.Dispose { + return globalWidgetHost.getDrawLock(mode); } export function headlessScope(dispatch: DispatchFunction): Scope { @@ -196,11 +210,13 @@ export interface Widget { * return the widget's text. return null to detach the widget. * may get called more often than the specified `fps`. * supports color codes but not ansi cursor movements. - */ format( + */ + format( now: ReturnType, ): | string - | null; /** 'null' to never update (use 'onChange'). defaults to 12 fps */ + | null; + /** 'null' to never update (use 'onChange') */ fps?: | number | null; /** Subscribe to manual widget updates. Call `rerender` when needed. */ @@ -211,26 +227,49 @@ export interface Widget { /** {@linkcode widgetHost}'s input takes terminal i/o as well as timing APIs */ export interface HeadlessWidgetEnv { - /** recieves ANSI escape sequences for interactive data */ - writeInteractive(text: string): void; - /** recieves log content (from `writeLine`) */ - writeOutput(text: string): void; + /** + * an exclusive lock on the terminal is held whenever widgets are active. a + * secondary purpose of this is to instrument/deinstrument other code to + * integrate with `log.ts`'s widget lock. for example, the node.js adapter + * will patch `process.std{out,err}` to ensure write calls properly get a + * draw lock. + * + * this lock can be cleared by deactiving all widgets, or by calling + * {@linkcode getDrawLock}. + * + * currently, this lock must be able to be synchronously aquired at any + * point. if you desire an async locking function, please contact me so we + * can design how it would work. you can currently work around this with + * `getDrawLock` + */ + lockTerminal: () => TerminalLock; + /** fast path for writing output without widgets */ + writeOutputTemporaryLock?: (buffer: string) => void; /** monotonic milliseconds */ - now(): ReturnType; + now: () => ReturnType; /** after resolving, `now()` should have increased by the delay time */ delay: typeof async.delay; - /** called often. */ +} + +export interface TerminalLock { + /** recieves ANSI escape sequences for interactive data (should flush immediately) */ + writeInteractive(text: string): void; + /** recieves log content from `write` (pre-buffered; should flush immediately) */ + writeOutput(text: string): void; + /** called often. TODO: convert this into a subscription */ getSize(): { columns: number; rows: number }; - /** called to enable input events */ - onInput?(write: (bytes: Uint8Array | string) => void): () => void; + /** temporarily free the lock */ + temporaryUnlock?(): () => void; + /** completely free the lock */ + close(): void; } /** an implementation of an ANSI-based widget host */ export interface HeadlessWidgetHost { /** see the top-level {@linkcode writeLine} function */ - writeLine(text: string): void; + write(text: string): void; /** see the top-level {@linkcode getDrawLock} function */ - getDrawLock(): ts.Dispose; + getDrawLock(mode: "long" | "short"): ts.Dispose; /** see the top-level {@linkcode startWidget} function */ startWidget(widget: Widget): ts.Dispose; /** stop all widgets and remove all timers. */ @@ -258,13 +297,13 @@ interface WidgetState { * - Maximum of one `wait` call at once. When the expected time suddenly * shrinks, the timer is rescheduled. * - When redrawing widget lines, three tricks are done to reduce flickering: - * 1. Tell the terminal not to flicker (ansi.syncStart/syncEnd) + * 1. Tell the terminal not to flicker (ansi.syncStart/syncEnd). * 2. A simple prefix-based diffing algorithm for skipping unchanged text * 3. Avoid clearing a line before redrawing it. * Points 2 and 3 are used for terminals that are slow or do not support sync. */ export function headlessWidgetHost(env: HeadlessWidgetEnv): HeadlessWidgetHost { - const { writeOutput, writeInteractive, now, delay, getSize } = env; + const { lockTerminal, now, delay, writeOutputTemporaryLock } = env; let timer: async.Cancelable | null = null; @@ -272,113 +311,146 @@ export function headlessWidgetHost(env: HeadlessWidgetEnv): HeadlessWidgetHost { let redrawTime = 0; let lastFlush = 0; let buffer = ""; + let partialLine = false; const widgets: Widget[] = []; const internals: WidgetState[] = []; let lines: string[] = []; + let hasSyncStart = false; + let terminal: TerminalLock | null = null; + let tempUnlock: (() => void) | null = null; function redrawCallback() { timer = null; redrawTime = (lastFlush = now()) - 0.00001; // windows time precision workaround + // trivial path when not using widgets if (!lines.length && !widgets.length) { - buffer && writeOutput(buffer); + ASSERT(buffer); + if (writeOutputTemporaryLock) { + writeOutputTemporaryLock(buffer); + if (hasSyncStart) { + terminal ??= lockTerminal(); + terminal.writeInteractive(ansi.syncEnd); + } + } else { + terminal ??= lockTerminal(); + buffer && terminal.writeOutput(buffer); + if (hasSyncStart) { + terminal ??= lockTerminal(); + terminal.writeInteractive(ansi.syncEnd); + } + terminal.close(); + terminal = null; + } buffer = ""; return; } - const { columns, rows } = getSize(); + terminal ??= lockTerminal(); + + const { columns, rows } = terminal.getSize(); let newWidgetLines: string[] = []; let next = Infinity; - if (widgets[0]) { - for (let w = 0, { length } = widgets; w < length; w += 1) { - const outText = UNWRAP(widgets[w]).format(lastFlush); - if (!outText) { - widgets.splice(w, 1); - UNWRAP(internals.splice(w, 1)[0]).unsub?.(); - w -= 1; - length -= 1; - continue; - } - const rowsLeft = Math.max(1, rows - newWidgetLines.length - 1); - if (rowsLeft === 1) break; - const lines = outText.split("\n").slice(0, rowsLeft); - newWidgetLines.push( - ...lines.map((line) => ansi.trimToWidth(line, columns - 1)), - ); - - next = Math.min(next, UNWRAP(internals[w]).frameTime); + for (let w = 0, { length } = widgets; w < length; w += 1) { + const outText = UNWRAP(widgets[w]).format(lastFlush); + if (!outText) { + widgets.splice(w, 1); + UNWRAP(internals.splice(w, 1)[0]).unsub?.(); + w -= 1; + length -= 1; + continue; } + const rowsLeft = Math.max(1, rows - newWidgetLines.length - 1); + if (rowsLeft === 1) break; + const lines = outText.split("\n").slice(0, rowsLeft); + newWidgetLines.push( + ...lines.map((line) => ansi.trimToWidth(line, columns - 1)), + ); - newWidgetLines = newWidgetLines.slice(0, rows - 1); + next = Math.min(next, UNWRAP(internals[w]).frameTime); } - + newWidgetLines = newWidgetLines.slice(0, rows - 1); if (next < Infinity) redrawSoon(next); if (!newWidgetLines[0]) { - if (lines.length) { - let clearLinesTop = Math.min( - lines.length, - string.countNewlines(buffer), - ); - writeInteractive( - ansi.startOfLine + - // skip up the shared widget space - ansi.cursorUp(lines.length) + - // clear the lines to contain `buffer` - (ansi.clearFullLine + ansi.startOfNextLine) - .repeat(clearLinesTop) + - ansi.cursorUp(clearLinesTop), + if (lines.length > 0) { + terminal.writeInteractive( + (hasSyncStart ? "" : ansi.syncStart) + + // clear the widget space + (ansi.cursorUp(1) + ansi.clearFullLine) + .repeat(lines.length) + + (partialLine ? ansi.cursorRestore : ""), ); + hasSyncStart = true; lines = []; } - buffer && writeOutput(buffer); + if (buffer) terminal.writeOutput(buffer); buffer = ""; + if (hasSyncStart) terminal.writeInteractive(ansi.syncEnd); return; } if (buffer) { - // do not perform diffing since the entire screen is moving down - // TODO: should lib/log handle wrapping? - let clearLinesTop = Math.min( + // when writing a buffer alongside widgets, the screen may look like this + // > [existing log] + // > [optional partial line] + // > [widget line 1] + // > [widget line 2] + // > [widget line 3] + // > [cursor is start of this line] + // + // first, clear out the space where new lines are going to intersect + const createsPartialLine = !buffer.endsWith("\n"); + // if more lines are buffered than there are widgets, only some are needed + const clearLinesTop = Math.min( lines.length, - string.countNewlines(buffer), + string.countNewlines(buffer) + + (createsPartialLine ? 1 : 0) + + (partialLine ? -1 : 0), ); const oldLines = lines.slice(clearLinesTop); - writeInteractive( - ansi.syncStart + (clearLinesTop > 0 - ? ansi.startOfLine + - // skip up the shared widget space - ansi.cursorUp(lines.length - clearLinesTop + 1) + - // clear the lines to contain `buffer` - ansi.clearFullLine + - (ansi.cursorUp(1) + ansi.clearFullLine) - .repeat(clearLinesTop - 1) - : ""), + terminal.writeInteractive( + (hasSyncStart ? "" : ansi.syncStart) + + ((clearLinesTop > 0 || partialLine) + // clear the lines for buffer + ? (clearLinesTop > 0 + ? ansi.cursorUp(lines.length - clearLinesTop + 1) + + ansi.clearFullLine + + (ansi.cursorUp(1) + ansi.clearFullLine) + .repeat(clearLinesTop - 1) + : "") + + (partialLine ? ansi.cursorRestore : "") + : ""), ); + partialLine = createsPartialLine; // then write output lines on standard out - writeOutput(buffer); - writeInteractive( - // the widget text - newWidgetLines.map((newLine, i) => - (newLine.includes("\x1b") && !newLine.endsWith(ansi.reset) - ? newLine + ansi.reset - : newLine) + - // clear rest of line if needed - (oldLines[i] && - ansi.widthInTerminal(oldLines[i]) > - ansi.widthInTerminal(newLine) - ? ansi.clearToEndOfLine - : "") + - "\n" - ).join("") + ansi.syncEnd, + terminal.writeOutput(buffer); + terminal.writeInteractive( + // if a partial line is created, then the widgets + // have to go on the next line, to avoid breaking stdout, + // the newline gets emitted on the interactive out. + (createsPartialLine ? ansi.cursorSave + "\n" : "") + + // the widget text + newWidgetLines.map((newLine, i) => + (newLine.includes("\x1b") && !newLine.endsWith(ansi.reset) + ? newLine + ansi.reset + : newLine) + + // clear rest of line if needed + (oldLines[i] && + ansi.widthInTerminal(oldLines[i]) > + ansi.widthInTerminal(newLine) + ? ansi.clearToEndOfLine + : "") + + "\n" + ).join("") + ansi.syncEnd, ); } else { const clearLinesBottom = Math.min( lines.length, Math.max(0, lines.length - (newWidgetLines?.length ?? 0)), ); - writeInteractive( - ansi.syncStart + ansi.startOfLine + + terminal.writeInteractive( + (hasSyncStart ? "" : ansi.syncStart) + // clear the bottom lines (clearLinesBottom ? (ansi.cursorUp(1) + ansi.clearToEndOfLine) @@ -402,6 +474,7 @@ export function headlessWidgetHost(env: HeadlessWidgetEnv): HeadlessWidgetHost { ansi.syncEnd, ); } + hasSyncStart = false; lines = newWidgetLines; buffer = ""; @@ -420,55 +493,87 @@ export function headlessWidgetHost(env: HeadlessWidgetEnv): HeadlessWidgetHost { timer.then(redrawCallback); } - function flushAndClear() { + function flushAndClear(shortTermDrawLock: boolean) { timer?.cancel(); timer = null; if (lines.length > 0) { - // clear widgets + UNWRAP(terminal).writeInteractive( + ansi.syncStart + + // clear the widget space + (ansi.cursorUp(1) + ansi.clearFullLine) + .repeat(lines.length) + + (partialLine ? ansi.cursorRestore : "") + + (shortTermDrawLock ? "" : ansi.syncEnd), + ); + lines = []; + hasSyncStart = shortTermDrawLock; + } + if (buffer.length > 0) { + if (widgets.length === 0 && writeOutputTemporaryLock) { + writeOutputTemporaryLock(buffer); + } else { + terminal ??= lockTerminal(); + terminal.writeOutput(buffer); + if (widgets.length === 0) { + terminal.close(); + terminal = null; + } + } + buffer = ""; } - if (buffer.length > 0) writeOutput(buffer), buffer = ""; } return { - writeLine(chunk) { - buffer += chunk + "\n"; - redrawSoon(0); + write(chunk) { + if (chunk) buffer += chunk, redrawSoon(0); }, - getDrawLock() { - if (locks === 0) flushAndClear(); + getDrawLock(mode) { + if (locks === 0) { + flushAndClear(mode === "short"); + if (widgets.length > 0 && terminal) { + if (terminal.temporaryUnlock) { + tempUnlock = terminal.temporaryUnlock(); + } else { + terminal.close(); + terminal = null; + } + } + } locks += 1; return ts.defer(() => { locks -= 1; if (locks === 0) { - if (buffer.length > 0) writeOutput(buffer), buffer = ""; - // TODO: reinit widget + tempUnlock?.(); + tempUnlock = null; + if (buffer.length > 0 || widgets.length > 0) redrawSoon(0); } }); }, startWidget(w) { - if (!widgets.includes(w)) { - const state: WidgetState = { - next: 0, - unsub: null, - frameTime: 1000 / (w.fps ?? 0), - }; - widgets.push(w); - internals.push(state); - state.unsub = w.onChange?.(() => { - state.next = 0; - redrawSoon(0); - }) ?? null; + ASSERT(!widgets.includes(w), "Cannot start the same widget twice."); + const state: WidgetState = { + next: 0, + unsub: null, + frameTime: 1000 / (w.fps ?? 0), + }; + widgets.push(w); + internals.push(state); + state.unsub = w.onChange?.(() => { + state.next = 0; redrawSoon(0); - } + }) ?? null; + redrawSoon(0); return ts.defer(() => { const i = widgets.indexOf(w); + if (i === -1) return; widgets.splice(i, 1); UNWRAP(internals.splice(i, 1)[0]).unsub?.(); redrawSoon(0); }); }, cancel() { - flushAndClear(); + flushAndClear(false); + widgets.splice(0, widgets.length); }, delay, now, @@ -500,7 +605,7 @@ let withinDispatch = false; let withinStackCapture = false; /** this class is an implementation detail */ -const ScopeImpl = class Scope implements Scope { +const ScopeImpl = class Scope implements RootScope { name: string | undefined; // TODO: this abstraction implementation has low performance. making every // scope define it's own dispatch is needed to correctly implement `tee`. @@ -561,6 +666,23 @@ const ScopeImpl = class Scope implements Scope { withinDispatch = false; }; + write: (text: string) => void = (text) => { + let frames; + if (!withinStackCapture) { + withinStackCapture = true; + frames = stack.capture().slice(2); + withinStackCapture = false; + } + this.writeMessage({ + level: "info", + scope: "", + newline: false, + text, + time: Date.now(), + stack: frames, + }); + }; + scoped(name: string): Scope { const current = this.name; return new Scope( @@ -584,16 +706,17 @@ const globalWidgetHost = /* @__PURE__ */ (() => { // return a no-op let warned = false; return { - writeLine: (line: string) => console.log(line), + write: (line: string) => console.log(line), getDrawLock: () => ts.defer(() => {}), startWidget: (w: Widget) => { if (!warned) { console.warn( '"@clo/lib/log.ts"\'s startWidget was called in an environment ' + - "that does not support the Node.js 'process' API. Widgets" + + "that does not support the Node.js 'process' API. Widgets " + "will not be visible.", ); } + warned = true; const close = w.onChange?.(() => {}); return ts.defer(close ?? (() => {})); }, @@ -601,29 +724,76 @@ const globalWidgetHost = /* @__PURE__ */ (() => { }; } const widget = headlessWidgetHost({ - writeOutput: (string) => process.stdout.write(string), - writeInteractive: (string) => process.stderr.write(string), + lockTerminal() { + const { stdout, stderr } = process; + let disposed = false; + + function patch( + fn: (this: T, ...args: A) => void, + ) { + return function (this: T, ...args: A) { + using _ = disposed ? null : widget.getDrawLock(); + fn.apply(this, args); + }; + } + + // patch calls to `process.std{out,err}` + // note: `pipe` uses managed calls to `write`, so this is plenty + const stdoutWrite = stdout.write; + const stderrWrite = stderr.write; + const stdoutEnd = stdout.end; + const stderrEnd = stderr.end; + const newStdoutWrite = stdout.write = patch( + stdoutWrite === node.builtin("stream")?.Writable.prototype.write + ? widget.write + : stdoutWrite, + ); + const newStderrWrite = stderr.write = patch(stderrWrite); + const newStdoutEnd = stdout.end = patch(stdoutEnd); + const newStderrEnd = stderr.end = patch(stderrEnd); + + // non-node runtimes will typically implement console in a way that + // doesn't use `node:process`, so it must also get patched + const console = globalThis + .console as unknown as Record void>; + const restoreConsole: [string, old: () => void, patch: () => void][] = []; + for (const [key, old] of Object.entries(console)) { + if (typeof old !== "function") continue; + try { + const patched = console[key] = patch(old); + restoreConsole.push([key, old, patched]); + } catch { /* skip */ } + } + + return { + writeOutput: (string) => stdoutWrite.call(stdout, string), + writeInteractive: (string) => stderrWrite.call(stderr, string), + getSize: () => process.stderr, + temporarilyUnlock() { + // no action needed + }, + close() { + disposed = true; + // leave patches in place if something else tampered with it. + if (stdout.write === newStdoutWrite) stdout.write = stdoutWrite; + if (stderr.write === newStderrWrite) stdout.write = stderrWrite; + if (stdout.end === newStdoutEnd) stdout.end = stdoutEnd; + if (stderr.end === newStderrEnd) stdout.end = stderrEnd; + for (const [key, old, patched] of restoreConsole) { + if (console[key] === patched) console[key] = old; + } + }, + }; + }, + writeOutputTemporaryLock(buffer: string) { + process.stdout.write(buffer); + }, now: () => performance.now(), delay: async.delay, - getSize: () => process.stderr, }); process.addListener("beforeExit", () => widget.cancel()); process.addListener("exit", () => widget.cancel()); - // Make sure the default `console` will not interweave with widgets - try { - const console = globalThis.console as unknown as Record; - for (const key of Object.keys(console)) { - const fn = console[key]; - if (typeof fn === "function") { - console[key] = function (...args: unknown[]) { - using _ = getDrawLock(); - fn.apply(this, args); - }; - } - } - } catch {} - return widget; })(); @@ -635,7 +805,7 @@ const levelToAnsi: Record = { }; let globalMessageFormatFunction: MessageFormatFunction = ( - { level, scope, text }, + { level, scope, text, newline }, colors, ) => { if (!text) return ""; @@ -648,7 +818,7 @@ let globalMessageFormatFunction: MessageFormatFunction = ( : scope ? `${level}(${scope}): ` : `${level}: `; - return prefix + text; + return prefix + text + (newline !== false ? "\n" : ""); }; let globalOutputFunction!: DispatchFunction; const globalLog = /* @__PURE__ */ (() => { @@ -656,7 +826,7 @@ const globalLog = /* @__PURE__ */ (() => { globalOutputFunction = node.process // In Node.js, coordinate with the widget host ? (message) => { - globalWidgetHost.writeLine(globalMessageFormatFunction(message, colors)); + globalWidgetHost.write(globalMessageFormatFunction(message, colors)); } // Otherwise, forward to `console` : (m) => { @@ -673,6 +843,13 @@ const globalLog = /* @__PURE__ */ (() => { })(); export type DispatchFunction = (message: Message) => void; +/** + * agnostic to the backend. should be able to format `newline: false` + * messages without a trailing newline, but not all backends may + * support this. + * + * TODO: change this to a `write`+`flush` pattern? + */ export type MessageFormatFunction = ( message: Message, colors: boolean, @@ -684,4 +861,4 @@ import * as node from "./node.ts"; import * as stack from "./log/stack.ts"; import * as string from "./string.ts"; import * as ts from "./ts.ts"; -import { UNWRAP } from "./assert.ts"; +import { ASSERT, UNWRAP } from "./assert.ts"; diff --git a/lib/node.ts b/lib/node.ts index b09aafb0cf1f287d1b00b095bbce87159c99ca39..43525b4126447ca3ed1d84cb8e4c7d6d10573bdb 100644 --- a/lib/node.ts +++ b/lib/node.ts @@ -27,6 +27,7 @@ interface Tty { columns: number; rows: number; addListener(event: string, callback: () => void): this; + end(text?: string | Uint8Array): void; write(text: string | Uint8Array): void; } @@ -54,6 +55,13 @@ interface Builtins { ...args: unknown[] ): string; }; + "stream": { + Writable: { + prototype: { + write: (value: string) => boolean; + }; + }; + }; } /** * Subset of Node.js binding types diff --git a/lib/progress.test.ts b/lib/progress.test.ts index 9b5c4f77864c03ff1a9cb4330965d95dd4ec8acb..4d791d13558bea8f1da75415c9c5ec6e5e69fc3c 100644 --- a/lib/progress.test.ts +++ b/lib/progress.test.ts @@ -4,13 +4,13 @@ test.skip("trivial end-to-end example", () => { const screen = new testing.MockScreen(); // create a mock terminal const root = new progress.Root(screen); // sync with mock timers progress.attachToScreen(root, screen); // attach `root` to the `screen` - assert.equal(screen.waitCalls.length, 0); // attaching does not render + assert.equal(screen.timers.entries.length, 0); // attaching does not render const a = root.start("hello"); const b = root.start("cats"); const _ = b.start("meow"); - assert.equal(screen.waitCalls.length, 1); + assert.equal(screen.timers.entries.length, 1); screen.expectFrame(1, { merged: "" }); // debounce // TODO: why the full resets? @@ -43,8 +43,8 @@ test.skip("trivial end-to-end example", () => { }); }); -describe("encodeEventStream", async (t) => { - await test("simple", async () => { +describe("encodeEventStream", (t) => { + test("simple", async () => { const root = new progress.Root(); // sync with mock timers const a = root.start("hello"); @@ -77,14 +77,14 @@ describe("encodeEventStream", async (t) => { }); // ## value formatters -test("slashValueFormatter", ({ mock }) => { - const fn = mock.fn((arg: number) => `<${arg}>`); +test("slashValueFormatter", () => { + const fn = vi.fn((arg: number) => `<${arg}>`); const fmt = progress.slashValueFormatter(fn); assert.equal(fmt(250, 0), "<250>"); - assert.equal(fn.mock.callCount(), 1); + assert.equal(fn.mock.calls.length, 1); assert.equal(fmt(250, 450), "<250>/<450>"); - assert.equal(fn.mock.callCount(), 3); + assert.equal(fn.mock.calls.length, 3); }); test("bytesValueFormatter", () => { assert.equal(progress.bytesValueFormatter(250, 0), "250B"); diff --git a/lib/progress.ts b/lib/progress.ts index f238c93c5d885b22a4123f6fda710cf0a07330ff..d86f9f2a18e2f3b55c0d8a7e4572b0def17a5916 100644 --- a/lib/progress.ts +++ b/lib/progress.ts @@ -753,9 +753,9 @@ export function formatUnicodeBar(progress: number, width: number): string { */ export function attachToScreen( root: Root, - { writeLine, startWidget }: Pick< + { write, startWidget }: Pick< log.HeadlessWidgetHost, - "writeLine" | "startWidget" + "write" | "startWidget" >, ): ts.Dispose { const stack = new DisposableStack(); @@ -774,7 +774,7 @@ export function attachToScreen( stack.use( root.on( "node-detached-log", - (msg) => writeLine(log.formatMessage(msg, true)), + (msg) => write(log.formatMessage(msg, true)), ), ); stack.use(root.on("node-end", (node) => { @@ -785,8 +785,8 @@ export function attachToScreen( if (logs.length > 0) { const count = `${logs.length} line${logs.length === 1 ? "" : "s"}`; const header = `[${count} from ${title}]`; - writeLine(ansi.style(ansi.fgBrightBlack, header)); - writeLine(logs.map((msg) => log.formatMessage(msg, true)).join("\n")); + write(ansi.style(ansi.fgBrightBlack, header) + "\n"); + write(logs.map((msg) => log.formatMessage(msg, true)).join("")); } })); @@ -1440,6 +1440,7 @@ function writeStreamEvent( if (msg.custom !== undefined) { w.stringWithLength(JSON.stringify(msg.custom)); } + // TODO: serialize newline attribute } } if (childrenSet !== undefined) { diff --git a/lib/testing.ts b/lib/testing.ts index 06937d1584bf534091be60cc25ce81ac6b68240c..2250ef41a8ca8248f3f68ee4160c14715e31a241 100644 --- a/lib/testing.ts +++ b/lib/testing.ts @@ -111,7 +111,7 @@ export class SyncPromise implements Promise { export class FakeTimers { time = 0; - timers: Array<{ + entries: Array<{ duration: number; resolve: () => void; src: stack.Frame[]; @@ -125,7 +125,8 @@ export class FakeTimers { const src = stack.capture(2); return async.makeCancelable( new SyncPromise((resolve) => { - this.timers.push({ + ASSERT(this.entries.length === 0); + this.entries.push({ duration: ms - this.waitTime, resolve, src, @@ -133,7 +134,8 @@ export class FakeTimers { this.waitTime = ms; }), () => { - throw new Error("TODO"); + ASSERT(this.entries.length === 1); + this.entries.length = 0; }, ); }; @@ -153,95 +155,105 @@ export class MockScreen implements Disposable, log.HeadlessWidgetHost { columns = 80; rows = 33; - time = 0; - stdout: string = ""; stderr: string = ""; out: string = ""; writeCalls = 0; - waitCalls: Array<{ - duration: number; - resolve: () => void; - src: stack.Frame[]; - }> = []; - waitTime = 0; + timers = new FakeTimers(); - writeLine: log.HeadlessWidgetHost["writeLine"]; + write: log.HeadlessWidgetHost["write"]; getDrawLock: log.HeadlessWidgetHost["getDrawLock"]; startWidget: log.HeadlessWidgetHost["startWidget"]; - cancel: log.HeadlessWidgetHost["cancel"]; delay: log.HeadlessWidgetHost["delay"]; now: log.HeadlessWidgetHost["now"]; + hasTerminalLock: null | "locked" | "temporary-unlock" = null; + static sync(text: string[]): string { return ansi.syncStart + text.join("") + ansi.syncEnd; } - constructor() { + constructor({ temporaryUnlocking }: { temporaryUnlocking?: boolean } = {}) { const host = log.headlessWidgetHost({ - writeInteractive: (text) => { - this.stderr += text; - this.out += text; - this.writeCalls += 1; - }, - writeOutput: (text) => { - this.stdout += text; - this.out += text; - this.writeCalls += 1; - }, - now: () => { - return this.time; - }, - delay: (ms) => { - const src = stack.capture(2); - return async.makeCancelable( - new SyncPromise((resolve) => { - this.waitCalls.push({ - duration: ms - this.waitTime, - resolve, - src, - }); - this.waitTime = ms; - }), - () => { - throw new Error("TODO"); + lockTerminal: () => { + ASSERT(!this.hasTerminalLock); + this.hasTerminalLock = "locked"; + return { + writeInteractive: (text) => { + this.stderr += text; + this.out += text; + this.writeCalls += 1; }, - ); - }, - getSize: () => { - return this; + writeOutput: (text) => { + this.stdout += text; + this.out += text; + this.writeCalls += 1; + }, + getSize: () => { + return this; + }, + temporaryUnlock: temporaryUnlocking + ? () => { + ASSERT(this.hasTerminalLock === "locked"); + this.hasTerminalLock = "temporary-unlock"; + return () => { + this.hasTerminalLock = "locked"; + }; + } + : undefined, + close: () => { + ASSERT(this.hasTerminalLock === "locked"); + this.hasTerminalLock = null; + }, + }; }, + now: this.timers.now, + delay: this.timers.delay, }); - this.writeLine = host.writeLine; + this.write = host.write; this.getDrawLock = host.getDrawLock; this.startWidget = host.startWidget; - this.cancel = host.cancel; this.delay = host.delay; this.now = host.now; } - expectFrame(ms: number, { stdout, stderr, merged: out }: { + expectNone() { + ASSERT(this.timers.entries.length === 0); + } + + expectWithoutConsume(ms: number) { + ASSERT(UNWRAP(this.timers.entries[0]).duration === 0); + } + + expectFrame(ms: number | null, { stdout, stderr, merged: out }: { stdout?: string; stderr?: string; merged?: string; }) { - const wait = UNWRAP(this.waitCalls.shift(), "no call to MockScreen.delay"); - ASSERT( - ms === wait.duration, - `expected ${ms}ms to pass, got ${wait.duration}, from:\n${ - wait.src.map((frame) => stack.formatFrame(frame, true)).join("\n") - }`, - ); + if (ms != null) { + const wait = UNWRAP( + this.timers.entries.shift(), + "no call to MockScreen.delay", + ); + ASSERT( + ms === wait.duration, + `expected ${ms}ms to pass, got ${wait.duration}, from:\n${ + wait.src.map((frame) => stack.formatFrame(frame, true)).join("\n") + }`, + ); - this.time += wait.duration; - this.waitTime = 0; - wait.resolve(); + this.timers.time += wait.duration; + this.timers.waitTime = 0; + wait.resolve(); + } else { + ASSERT(this.timers.entries.length === 0); + } ASSERT( out == null || this.out === out, () => - `interweved out does not match\n` + + `merged out does not match\n` + `expected: ${ansi.debugAnsi(out ?? "")}\n` + `actual: ${ansi.debugAnsi(this.out)}\n`, ); @@ -265,9 +277,12 @@ export class MockScreen implements Disposable, log.HeadlessWidgetHost { } [Symbol.dispose]() { - ASSERT(this.waitCalls.length === 0, "there is a pending write!"); - ASSERT(!this.stdout, "unread standard out" + this.stdout); - ASSERT(!this.stderr, "unread interactive out" + this.stderr); + this.cancel(); + } + cancel() { + ASSERT(this.timers.entries.length === 0, "there is a pending write!"); + ASSERT(!this.stdout, "unread standard out: " + this.stdout); + ASSERT(!this.stderr, "unread interactive out: " + this.stderr); } } -- 2.54.0