From a74b35e546be0d1d10c1da28e8daedec77ad69b4 Mon Sep 17 00:00:00 2001 From: clover caruso Date: Wed, 15 Oct 2025 23:36:01 -0700 Subject: [PATCH] feat(lib/log): output redirection with `tee` also resolves #40 --- lib/log.test.ts | 222 +++++++++++++++----------------------------- lib/log.ts | 124 ++++++++++++++++--------- lib/testing.ts | 239 ++++++++++++++++++++++++++++++++++++++++++++++++ 3 files changed, 391 insertions(+), 194 deletions(-) create mode 100644 lib/testing.ts diff --git a/lib/log.test.ts b/lib/log.test.ts index 65559bbcef81a272a595233fde3b1b6dfea9895f..9d8bd587a16b0ae56cbd782f2d6f116f7d7ed532 100644 --- a/lib/log.test.ts +++ b/lib/log.test.ts @@ -1,164 +1,86 @@ -import { ASSERT, UNWRAP } from "lib/assert.ts"; -import { test } from "node:test"; -import * as headless from "lib/log/headless.ts"; -import * as log from "lib/log.ts"; - -log satisfies log.Scope; // the namespace import is a valid Scope - -test("writeLine buffers", () => { - using host = new TestWidgetHost(); - host.writeLine("hello world"); - host.writeLine("and so on"); - host.expectFrame(0, { - stdout: "hello world\nand so on\n", - }); - host.writeLine("more logs"); - host.expectFrame(0, { - stdout: "more logs\n", +// the namespace import is a valid Scope +log satisfies log.Scope; + +// these tests for `startWidget` are built on a custom widget host +// 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"); + host.expectFrame(0, { + stdout: "hello world\nand so on\n", + }); + host.writeLine("more logs"); + host.expectFrame(0, { + stdout: "more logs\n", + }); }); -}); -test("widget with interweaving logs", () => { - const host = new TestWidgetHost(); + test("widget with interweaving logs", () => { + using host = new testing.MockScreen(); - const _ = host.startWidget({ - format: (now) => `line one ${now}\nline two`, - }); + using _ = host.startWidget({ + format: (now) => `line one ${now}\nline two`, + }); - host.expectFrame(0, { - stderr: sync([ - ansi.startOfLine, - "line one 0\nline two\n", - ]), - }); + host.expectFrame(0, { + stderr: testing.MockScreen.sync([ + ansi.startOfLine, + "line one 0\nline two\n", + ]), + }); - host.writeLine("info: line of log"); - host.expectFrame(0, { - out: sync([ - ansi.startOfLine, - ansi.cursorUp(2), - ansi.clearFullLine, - "info: line of log\n", - "line one 0\nline two\n", - ]), - }); + host.writeLine("info: line of log"); + host.expectFrame(0, { + merged: testing.MockScreen.sync([ + ansi.startOfLine, + ansi.cursorUp(2), + ansi.clearFullLine, + "info: line of log\n", + "line one 0\nline two\n", + ]), + }); - host.writeLine("warn: line of log"); - host.writeLine("error: line of log"); - host.expectFrame(0, { - out: sync([ - ansi.startOfLine, - ansi.cursorUp(1), - ansi.clearFullLine, - ansi.cursorUp(1), - ansi.clearFullLine, - "warn: line of log\n", - "error: line of log\n", - "line one 0\nline two\n", - ]), + host.writeLine("warn: line of log"); + host.writeLine("error: line of log"); + host.expectFrame(0, { + merged: testing.MockScreen.sync([ + ansi.startOfLine, + ansi.cursorUp(1), + ansi.clearFullLine, + ansi.cursorUp(1), + ansi.clearFullLine, + "warn: line of log\n", + "error: line of log\n", + "line one 0\nline two\n", + ]), + }); }); -}); - -function sync(text: string[]) { - return ansi.syncStart + text.join("") + ansi.syncEnd; -} - -class TestWidgetHost implements headless.WidgetHost { - columns = 80; - rows = 33; - - now = 0; - - stdout: string = ""; - stderr: string = ""; - out: string = ""; - writeCalls = 0; - waitDuration = 0; - waiter: (() => void) | null = null; + test("widget with logs in same frame", () => { + using host = new testing.MockScreen(); - writeLine: headless.WidgetHost["writeLine"]; - getDrawLock: headless.WidgetHost["getDrawLock"]; - startWidget: headless.WidgetHost["startWidget"]; - cancel: headless.WidgetHost["cancel"]; + host.writeLine("log line 1"); + host.writeLine("log line 2"); - constructor() { - const host = headless.widgetHost({ - 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.now; - }, - wait: (ms, cb) => { - this.waitDuration = ms; - this.waiter = cb; - return () => this.waiter = null; - }, - getSize: () => { - return this; - }, + using _ = host.startWidget({ + format: (now) => `widget line one ${now}\nwidget line two`, }); - this.writeLine = host.writeLine; - this.getDrawLock = host.getDrawLock; - this.startWidget = host.startWidget; - this.cancel = host.cancel; - } - expectFrame(ms: number, { stdout, stderr, out }: { - stdout?: string; - stderr?: string; - out?: string; - }) { - const { waitDuration } = this; - ASSERT( - ms === waitDuration, - `expected ${ms}ms to pass, only ${waitDuration}`, - ); - - const callback = UNWRAP(this.waiter, "no pending frame"); - this.waiter = null; - this.now += this.waitDuration; - callback(); - - ASSERT( - out == null || this.out === out, - () => - `interweved out does not match\n` + - `expected: ${ansi.debugAnsi(out ?? "")}\n` + - `actual: ${ansi.debugAnsi(this.out)}\n`, - ); - ASSERT( - stdout == null || this.stdout === stdout, - () => - `standard out does not match\n` + - `expected: ${ansi.debugAnsi(stdout ?? "")}\n` + - `actual: ${ansi.debugAnsi(this.stdout)}\n`, - ); - ASSERT( - stderr == null || this.stderr === stderr, - () => - `interactive out does not match\n` + - `expected: ${ansi.debugAnsi(stderr ?? "")}\n` + - `actual: ${ansi.debugAnsi(this.stderr)}\n`, - ); - this.stdout = ""; - this.stderr = ""; - this.out = ""; - } - - [Symbol.dispose]() { - ASSERT(!this.waiter, "there is a pending write!"); - ASSERT(!this.stdout, "unread standard out" + this.stdout); - ASSERT(!this.stderr, "unread interactive out" + this.stderr); - } -} + host.expectFrame(0, { + stdout: "log line 1\nlog line 2\n", + merged: testing.MockScreen.sync([ + "log line 1\n", + "log line 2\n", + "widget line one 0\nwidget line two\n", + ]), + }); + }); +}); +import { describe, test } from "node:test"; import * as ansi from "./string/ansi.ts"; +import * as log from "./log.ts"; +import * as testing from "./testing.ts"; diff --git a/lib/log.ts b/lib/log.ts index 2bccef7bd33087c76ae885b59f4c1d728525cba5..0f7e296f987ece8f6e80040931ef9aa8eb44cb26 100644 --- a/lib/log.ts +++ b/lib/log.ts @@ -34,7 +34,8 @@ * - otherwise, logs are surfaced using the global `console` API * * 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 set up + * `log.tee()` to duplicate all messages elsewhere. for example, a project may + * configure logs to upload to a telemetry service. * * @module */ @@ -123,10 +124,29 @@ export function log(...args: unknown[]) { export function debug(...args: unknown[]) { globalLog.debug(...args); } - +/** create a named logging scope */ export function scoped(name: string): Scope { return globalLog.scoped(name); } +/** redirect all log messages to another writer */ +export function tee(destination: DispatchFunction): ts.Dispose { + return globalLog.tee(destination); +} +/** replace the default writer */ +export function replaceGlobalDestination(destination: DispatchFunction) { + globalOutputFunction = destination; +} + +/** replace the default formatter */ +export function replaceGlobalFormatFunction( + format: (msg: Message, colors: boolean) => string, +) { + globalMessageFormatFunction = format; +} + +export function formatMessage(msg: Message, colors: boolean) { + return globalMessageFormatFunction(msg, colors); +} /** * a widget is an interactive display that persists at the end @@ -169,7 +189,7 @@ export function headlessScope(dispatch: DispatchFunction): Scope { return new Scope(dispatch); } -/** See {@linkcode startWidget} */ +/** see {@linkcode startWidget} */ export interface Widget { /** * return the widget's text. return null to detach the widget. @@ -190,17 +210,17 @@ 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. */ + /** recieves ANSI escape sequences for interactive data */ writeInteractive(text: string): void; - /** Recieves log content (from `writeLine`). */ + /** recieves log content (from `writeLine`) */ writeOutput(text: string): void; - /** Monotonic. */ + /** monotonic milliseconds */ now(): ReturnType; - /** 0ms indicates "one frame". */ - wait(ms: number, cb: () => void): () => void; - /** Called often. */ + /** after resolving, `now()` should have increased by the delay time */ + delay: typeof async.delay; + /** called often. */ getSize(): { columns: number; rows: number }; - /** Called to enable input events */ + /** called to enable input events */ onInput?(write: (bytes: Uint8Array | string) => void): () => void; } @@ -214,8 +234,13 @@ export interface HeadlessWidgetHost { startWidget(widget: Widget): ts.Dispose; /** stop all widgets and remove all timers. */ cancel(): void; + /** generic delay function */ + delay?: typeof async.delay; + /** generic now function */ + now?: typeof performance.now; } +/** @internal state */ interface WidgetState { frameTime: number; next: number; @@ -238,10 +263,9 @@ interface WidgetState { * 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, wait, getSize } = env; - type Cancel = ReturnType; + const { writeOutput, writeInteractive, now, delay, getSize } = env; - let timer: Cancel | null = null; + let timer: async.Cancelable | null = null; let locks = 0; let redrawTime = 0; @@ -313,20 +337,22 @@ export function headlessWidgetHost(env: HeadlessWidgetEnv): HeadlessWidgetHost { if (buffer) { // do not perform diffing since the entire screen is moving down - // TODO: should i handle wrapping? + // TODO: should lib/log handle wrapping? let clearLinesTop = Math.min( lines.length, string.countNewlines(buffer), ); const oldLines = lines.slice(clearLinesTop); writeInteractive( - ansi.syncStart + 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), + 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) + : ""), ); // then write output lines on standard out writeOutput(buffer); @@ -385,15 +411,16 @@ export function headlessWidgetHost(env: HeadlessWidgetEnv): HeadlessWidgetHost { const newRedrawTime = now() + ms; if (timer) { if (redrawTime < newRedrawTime) return; - timer(); // cancel previous + timer.cancel(); // cancel previous timer = null; } redrawTime = newRedrawTime + 1; - timer = wait(ms, redrawCallback); + timer = delay(ms); + timer.then(redrawCallback); } function flushAndClear() { - timer?.(); + timer?.cancel(); timer = null; if (lines.length > 0) { // clear widgets @@ -442,6 +469,8 @@ export function headlessWidgetHost(env: HeadlessWidgetEnv): HeadlessWidgetHost { cancel() { flushAndClear(); }, + delay, + now, }; } @@ -469,6 +498,7 @@ let formatLine = /* @__PURE__ */ (() => { let withinDispatch = false; let withinStackCapture = false; +/** this class is an implementation detail */ const Scope = class Scope implements Scope { name: string | undefined; // TODO: this abstraction implementation has low performance. making every @@ -544,7 +574,7 @@ const Scope = class Scope implements Scope { }; const globalWidgetHost = /* @__PURE__ */ (() => { - // TODO; write this in a tree-shakable manner + // TODO; write this in a more tree-shakable manner const { process } = node; if (!process || !process.stderr.isTTY) { // return a no-op @@ -570,10 +600,7 @@ const globalWidgetHost = /* @__PURE__ */ (() => { writeOutput: (string) => process.stdout.write(string), writeInteractive: (string) => process.stderr.write(string), now: () => performance.now(), - wait: (ms, cb) => { - const id = setTimeout(cb, ms); - return () => clearTimeout(id); - }, + delay: async.delay, getSize: () => process.stderr, }); process.addListener("beforeExit", () => widget.cancel()); @@ -603,23 +630,29 @@ const levelToAnsi: Record = { debug: `${ansi.dim}dbg`, }; +let globalMessageFormatFunction: MessageFormatFunction = ( + { level, scope, text }, + colors, +) => { + if (!text) return ""; + const prefix = colors + // colorful + ? `${levelToAnsi[level]}${ + scope ? `(${scope})` : "" + }${ansi.fgReset}${ansi.dim}:${ansi.reset} ` + // colorless + : scope + ? `${level}(${scope}): ` + : `${level}: `; + return prefix + text; +}; let globalOutputFunction!: DispatchFunction; const globalLog = /* @__PURE__ */ (() => { const colors = node.process?.stderr.isTTY ?? false; globalOutputFunction = node.process // In Node.js, coordinate with the widget host - ? ({ level, scope, text }) => { - if (!text) return globalWidgetHost.writeLine(""); - const prefix = colors - // colorful - ? `${levelToAnsi[level]}${ - scope ? `(${scope})` : "" - }${ansi.fgReset}${ansi.dim}:${ansi.reset} ` - // colorless - : scope - ? `${level}(${scope}): ` - : `${level}: `; - globalWidgetHost.writeLine(prefix + text); + ? (message) => { + globalWidgetHost.writeLine(globalMessageFormatFunction(message, colors)); } // Otherwise, forward to `console` : (m) => { @@ -635,11 +668,14 @@ const globalLog = /* @__PURE__ */ (() => { return new Scope(globalOutputFunction); })(); -export interface DispatchFunction { - (message: Message): void; -} +export type DispatchFunction = (message: Message) => void; +export type MessageFormatFunction = ( + message: Message, + colors: boolean, +) => string; import * as ansi from "./string/ansi.ts"; +import * as async from "./async.ts"; import * as node from "./node.ts"; import * as stack from "./log/stack.ts"; import * as string from "./string.ts"; diff --git a/lib/testing.ts b/lib/testing.ts new file mode 100644 index 0000000000000000000000000000000000000000..11e8586da0d1279936d56152d85e7dd5e551b8c9 --- /dev/null +++ b/lib/testing.ts @@ -0,0 +1,239 @@ +/** + * @module contains some utilities for writing tests. many are only useful for + * testing against other library modules. + */ + +/** + * implements `Promise` but reactions are emitted instantly. + * + * this is used for some tests where the promise interface is used in a + * synchronous way. an example of this is the log and progress tests use this + * to satisfy the async interface function for `delay` but using code that runs + * fully synchronously. + */ +export class SyncPromise implements Promise { + [Symbol.toStringTag] = "SyncPromise"; + #status: "pending" | "resolved" | "rejected" = "pending"; + #value: unknown = null; + #resolve: Array<(value: T) => void> = []; + #reject: Array<(error: unknown) => void> = []; + #finally: Array<() => void> = []; + + constructor( + init: ( + resolve: (value: T) => void, + reject: (error: unknown) => void, + ) => void, + ) { + init( + (value) => { + if (this.#status !== "pending") return; + this.#status = "resolved"; + this.#value = value; + this.#resolve.forEach((cb) => cb(value)); + this.#finally.forEach((cb) => cb()); + }, + (error) => { + if (this.#status !== "pending") return; + this.#status = "rejected"; + this.#value = error; + if (this.#reject.length === 0) throw error; + this.#reject.forEach((cb) => cb(error)); + this.#finally.forEach((cb) => cb()); + }, + ); + } + + then( + onfulfilled?: + | ((value: T) => TResult1 | PromiseLike) + | null + | undefined, + onrejected?: + | ((reason: any) => TResult2 | PromiseLike) + | null + | undefined, + ): Promise { + if (this.#status === "rejected") throw this.#value; + if (this.#status === "resolved") { + const result = onfulfilled + ? onfulfilled(this.#value as T) + : this.#value as T; + return new SyncPromise((resolve) => { + if (typeof result === "object" && result && "then" in result) { + result.then?.(resolve); + } else { + resolve(result as TResult1); + } + }); + } + let resolve: (value: TResult1 | TResult2) => void; + let reject: (error: unknown) => void; + function react( + value: X, + reactor: ( + value: X, + ) => TResult1 | TResult2 | PromiseLike, + ) { + try { + const result = reactor(value); + if (typeof result === "object" && result && "then" in result) { + result.then?.(resolve); + } else { + resolve(result); + } + } catch (error) { + reject(error); + } + } + this.#resolve.push((value) => onfulfilled && react(value, onfulfilled)); + if (onrejected) this.#reject.push((value) => react(value, onrejected)); + return new SyncPromise((innerResolve, innerReject) => { + resolve = innerResolve; + reject = innerReject; + }); + } + catch( + onrejected?: + | ((reason: any) => TResult | PromiseLike) + | null + | undefined, + ): Promise { + return this.then((x) => x, onrejected); + } + finally(onfinally?: (() => void) | null | undefined): Promise { + if (!onfinally) return this; + if (this.#status === "pending") this.#finally.push(onfinally); + else onfinally(); + return this; + } +} + +/** implements a log.HeadlessWidgetHost that acts as a fake screen. */ +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; + + writeLine: log.HeadlessWidgetHost["writeLine"]; + getDrawLock: log.HeadlessWidgetHost["getDrawLock"]; + startWidget: log.HeadlessWidgetHost["startWidget"]; + cancel: log.HeadlessWidgetHost["cancel"]; + delay: log.HeadlessWidgetHost["delay"]; + now: log.HeadlessWidgetHost["now"]; + + static sync(text: string[]) { + return ansi.syncStart + text.join("") + ansi.syncEnd; + } + + constructor() { + 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"); + }, + ); + }, + getSize: () => { + return this; + }, + }); + this.writeLine = host.writeLine; + 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 }: { + 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") + }`, + ); + + this.time += wait.duration; + this.waitTime = 0; + wait.resolve(); + + ASSERT( + out == null || this.out === out, + () => + `interweved out does not match\n` + + `expected: ${ansi.debugAnsi(out ?? "")}\n` + + `actual: ${ansi.debugAnsi(this.out)}\n`, + ); + ASSERT( + stdout == null || this.stdout === stdout, + () => + `standard out does not match\n` + + `expected: ${ansi.debugAnsi(stdout ?? "")}\n` + + `actual: ${ansi.debugAnsi(this.stdout)}\n`, + ); + ASSERT( + stderr == null || this.stderr === stderr, + () => + `interactive out does not match\n` + + `expected: ${ansi.debugAnsi(stderr ?? "")}\n` + + `actual: ${ansi.debugAnsi(this.stderr)}\n`, + ); + this.stdout = ""; + this.stderr = ""; + this.out = ""; + } + + [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); + } +} + +import * as ansi from "lib/string/ansi.ts"; +import { ASSERT, UNWRAP } from "lib/assert.ts"; +import * as log from "lib/log.ts"; +import * as async from "lib/async.ts"; +import * as stack from "lib/log/stack.ts"; -- 2.54.0