From bd0b975ad9158013a4e9c6a55b0a7cc3170e33a8 Mon Sep 17 00:00:00 2001 From: Goran Gajic Date: Thu, 13 Aug 2026 15:19:09 +0200 Subject: [PATCH 1/4] feat(runner): make run --follow quiet, stream logs behind --logs --follow buried the started/passed/failed signal under every log line the run produced. It now reads only run-status and reports the run's status events; the new --logs flag (implying --follow) restores the full run-logs stream. Not --verbose: the program already claims that flag for debug logging, and a program-level option would swallow it. NOVA-1544 --- .changeset/quiet-runner-follow.md | 5 ++ skills/qawolf-cli/references/runner.md | 11 ++- src/commands/__snapshots__/help.test.ts.snap | 6 +- src/commands/program.test.ts | 23 +++++ src/commands/runner/run.register.ts | 24 ++++- src/core/interactiveRunner/journal.ts | 21 +++++ src/core/messages/interactiveRunner.ts | 1 + .../interactiveRunner/followRun.quiet.test.ts | 90 +++++++++++++++++++ .../interactiveRunner/followRun.test.ts | 27 +++--- src/domains/interactiveRunner/followRun.ts | 74 ++++++++------- .../interactiveRunner/runFlow.follow.test.ts | 67 ++++++++++++++ src/domains/interactiveRunner/runFlow.test.ts | 47 ++-------- src/domains/interactiveRunner/runFlow.ts | 7 +- 13 files changed, 309 insertions(+), 94 deletions(-) create mode 100644 .changeset/quiet-runner-follow.md create mode 100644 src/domains/interactiveRunner/followRun.quiet.test.ts create mode 100644 src/domains/interactiveRunner/runFlow.follow.test.ts diff --git a/.changeset/quiet-runner-follow.md b/.changeset/quiet-runner-follow.md new file mode 100644 index 000000000..24595298e --- /dev/null +++ b/.changeset/quiet-runner-follow.md @@ -0,0 +1,5 @@ +--- +"@qawolf/cli": minor +--- + +`qawolf runner run --follow` now reports only the run's status — an "in progress" line, then whether it passed or failed — instead of streaming every log line the run produces. The full log stream is available behind the new `--logs` flag, which implies `--follow`. Anything parsing a followed run's stdout should expect status entries by default and pass `--logs` to keep receiving log lines. diff --git a/skills/qawolf-cli/references/runner.md b/skills/qawolf-cli/references/runner.md index 22bf19d03..e884520e8 100644 --- a/skills/qawolf-cli/references/runner.md +++ b/skills/qawolf-cli/references/runner.md @@ -166,13 +166,16 @@ The call answers with a run id as soon as the run is accepted. **The outcome is not in that answer**, it is in the `run-status` stream, whose entries carry `runId`, `status` and an `errorMessage` when there is one. -**Pass `--follow` to `run` and let it wait for you.** It streams the run's logs -and ends on the settled status, never on the logs, so a run that prints nothing -still terminates the follow and a run that dies mid-sentence still reports how. -Exit code `1` means the run did not pass. +**Pass `--follow` to `run` and let it wait for you.** It reports the run's +status — in progress, then passed or failed — and ends on the settled status. +Exit code `1` means the run did not pass. Add `--logs` to also stream every +log line the run produces; the follow still ends on the status, never on the +logs, so a run that prints nothing still terminates the follow and a run that +dies mid-sentence still reports how. ```sh qawolf runner run flows/checkout.flow.ts --follow +qawolf runner run flows/checkout.flow.ts --follow --logs ``` If you would rather submit and come back later, note that `--follow` on `events` diff --git a/src/commands/__snapshots__/help.test.ts.snap b/src/commands/__snapshots__/help.test.ts.snap index e021955be..24b077a63 100644 --- a/src/commands/__snapshots__/help.test.ts.snap +++ b/src/commands/__snapshots__/help.test.ts.snap @@ -328,7 +328,10 @@ Run a flow on an interactive runner, shipping the current directory's files with it Options: - --follow Stream the run's logs until it settles (default: false) + --follow Report the run's status until it settles: in progress, + then passed or failed (default: false) + --logs Stream every log line the run produces while following. + Implies --follow (default: false) --runner Runner to target. Defaults to QAWOLF_RUNNER_ID, then this directory's stored runner --timeout Give up following after this long. Following keeps the @@ -339,6 +342,7 @@ Options: Examples: $ qawolf runner run flows/checkout.flow.ts $ qawolf runner run flows/checkout.flow.ts --follow + $ qawolf runner run flows/checkout.flow.ts --follow --logs " `; diff --git a/src/commands/program.test.ts b/src/commands/program.test.ts index e8eaedf44..a9124d99e 100644 --- a/src/commands/program.test.ts +++ b/src/commands/program.test.ts @@ -96,6 +96,29 @@ describe("createProgram", () => { } }); + // A program-level option matches anywhere on the command line, so a + // subcommand redefining one gets a flag that parses but never reaches its + // handler: the program consumes it first. + it("no subcommand redefines a program-level option", () => { + const program = createProgram({ signals: noopSignals }); + const globalFlags = new Set(program.options.map((option) => option.long)); + + const collisions: string[] = []; + const walk = (commands: readonly (typeof program)[]): void => { + for (const command of commands) { + for (const option of command.options) { + if (option.long !== undefined && globalFlags.has(option.long)) { + collisions.push(`${command.name()} ${option.long}`); + } + } + walk(command.commands as (typeof program)[]); + } + }; + walk(program.commands as (typeof program)[]); + + expect(collisions).toEqual([]); + }); + it("throws on unknown option", () => { let err: unknown; try { diff --git a/src/commands/runner/run.register.ts b/src/commands/runner/run.register.ts index 14739b559..253570ec0 100644 --- a/src/commands/runner/run.register.ts +++ b/src/commands/runner/run.register.ts @@ -13,7 +13,8 @@ import { runnerDeps, runnerFlagDescription } from "./context.js"; const runExamples = ` Examples: $ qawolf runner run flows/checkout.flow.ts - $ qawolf runner run flows/checkout.flow.ts --follow`; + $ qawolf runner run flows/checkout.flow.ts --follow + $ qawolf runner run flows/checkout.flow.ts --follow --logs`; const eventsExamples = ` Examples: @@ -21,7 +22,12 @@ Examples: $ qawolf runner events run-logs --run --follow $ qawolf runner events console --since 120 --json`; -type RunFlags = { follow: boolean; runner?: string; timeout: string }; +type RunFlags = { + follow: boolean; + logs: boolean; + runner?: string; + timeout: string; +}; type EventsFlags = { follow: boolean; @@ -40,7 +46,18 @@ export function registerRunnerRunCommands( .description( "Run a flow on an interactive runner, shipping the current directory's files with it", ) - .option("--follow", "Stream the run's logs until it settles", false) + .option( + "--follow", + "Report the run's status until it settles: in progress, then passed or failed", + false, + ) + // Not --verbose: the program already claims that flag for debug logging, + // and Commander lets a program-level option swallow it from any position. + .option( + "--logs", + "Stream every log line the run produces while following. Implies --follow", + false, + ) .option("--runner ", runnerFlagDescription) .option( "--timeout ", @@ -55,6 +72,7 @@ export function registerRunnerRunCommands( { entryPoint: file, follow: opts.follow, + logs: opts.logs, runner: opts.runner, timeout: opts.timeout, }, diff --git a/src/core/interactiveRunner/journal.ts b/src/core/interactiveRunner/journal.ts index 4775c3616..05d3d4514 100644 --- a/src/core/interactiveRunner/journal.ts +++ b/src/core/interactiveRunner/journal.ts @@ -71,6 +71,27 @@ export function readRunSettlement(payload: unknown): RunSettlement { }; } +export type SettledRun = + | { type: "passed" } + | { type: "failed"; errorMessage: string | undefined } + | { type: "unrecognized"; status: string }; + +/** The first settling entry in a window of `run-status` entries, if any. */ +export function findSettlement( + entries: readonly { payload: unknown }[], +): SettledRun | undefined { + for (const entry of entries) { + const settlement = readRunSettlement(entry.payload); + if (settlement.type !== "settled") continue; + if (settlement.status === "passed") return { type: "passed" }; + if (settlement.status === "failed") { + return { errorMessage: settlement.errorMessage, type: "failed" }; + } + return { status: settlement.status, type: "unrecognized" }; + } + return undefined; +} + /** * A run's own log line, as much of it as the CLI renders. Tolerant for the same * reason as above: an entry it cannot read is printed as JSON rather than diff --git a/src/core/messages/interactiveRunner.ts b/src/core/messages/interactiveRunner.ts index 3e6673d3a..72046ae22 100644 --- a/src/core/messages/interactiveRunner.ts +++ b/src/core/messages/interactiveRunner.ts @@ -57,6 +57,7 @@ export const interactiveRunnerMessages = { errorMessage === undefined ? "The run failed and reported no reason." : `The run failed: ${errorMessage}`, + runInProgress: "The run is in progress.", runPassed: "The run passed.", runSettledUnknown: (status: string) => `The run settled as "${status}", which this version of the CLI does not recognize. Upgrade to read it.`, diff --git a/src/domains/interactiveRunner/followRun.quiet.test.ts b/src/domains/interactiveRunner/followRun.quiet.test.ts new file mode 100644 index 000000000..5af420d51 --- /dev/null +++ b/src/domains/interactiveRunner/followRun.quiet.test.ts @@ -0,0 +1,90 @@ +import { describe, expect, it } from "bun:test"; + +import { followRun } from "./followRun.js"; +import { makeAuthCtx, makeTestDeps } from "./deps.testUtils.js"; +import { makeJournal } from "./journal.testUtils.js"; + +const inProgress = { runId: "run-a", status: "in-progress" }; +const passed = { runId: "run-a", status: "passed" }; + +const follow = (ctx: ReturnType["ctx"]) => + followRun( + ctx, + { logs: false, runId: "run-a", runnerId: "ci", timeoutSeconds: 3600 }, + makeTestDeps(), + ); + +describe("followRun without --logs, the quiet default", () => { + it("reports the run's status events and that it passed", async () => { + const { callPublicApi, ctx, streamed } = makeAuthCtx(); + callPublicApi.mockImplementation( + makeJournal({ + "run-logs": [[{ message: "starting", runId: "run-a" }]], + "run-status": [[inProgress], [passed]], + }), + ); + + expect(await follow(ctx)).toBeUndefined(); + + expect(streamed()).toEqual(["The run is in progress."]); + expect(ctx.ui.success).toHaveBeenCalled(); + }); + + // Never read, not read-and-dropped: each poll of a stream nothing is printed + // from would be a wasted request to the runner. + it("does not read the logs", async () => { + const { callPublicApi, ctx } = makeAuthCtx(); + callPublicApi.mockImplementation(makeJournal({ "run-status": [[passed]] })); + + await follow(ctx); + + const streams = callPublicApi.mock.calls.map( + ([, input]) => (input as { stream: string }).stream, + ); + expect(streams).toEqual(["run-status"]); + }); + + // The runner is free to write `in-progress` more than once (a heartbeat, a + // retry); repeating the line would make the quiet mode noisy again. + it("reports the run in progress once, however many entries say so", async () => { + const { callPublicApi, ctx, streamed } = makeAuthCtx(); + callPublicApi.mockImplementation( + makeJournal({ + "run-status": [[inProgress], [inProgress, inProgress], [passed]], + }), + ); + + expect(await follow(ctx)).toBeUndefined(); + expect(streamed()).toEqual(["The run is in progress."]); + }); + + // Liveness detection rides on `run-status` alone here, so the unreachable + // grace window has to work without a second stream answering. + it("keeps going through a runner that is not answering yet", async () => { + const { callPublicApi, ctx, streamed } = makeAuthCtx(); + callPublicApi.mockImplementation( + makeJournal({ + "run-status": ["unreachable", "unreachable", [inProgress], [passed]], + }), + ); + + expect(await follow(ctx)).toBeUndefined(); + expect(streamed()).toEqual(["The run is in progress."]); + }); + + // Under --json a rendered sentence is prose on a stream that owes its reader + // JSON, so the status entry travels beside it and json mode prints the entry. + it("hands the whole status entry to the renderer", async () => { + const { callPublicApi, ctx, streamedData } = makeAuthCtx(); + callPublicApi.mockImplementation( + makeJournal({ "run-status": [[inProgress], [passed]] }), + ); + + await follow(ctx); + + expect(streamedData()[0]).toMatchObject({ + payload: { status: "in-progress" }, + sequence: 1, + }); + }); +}); diff --git a/src/domains/interactiveRunner/followRun.test.ts b/src/domains/interactiveRunner/followRun.test.ts index 0e2eae953..5143fe4cf 100644 --- a/src/domains/interactiveRunner/followRun.test.ts +++ b/src/domains/interactiveRunner/followRun.test.ts @@ -15,16 +15,23 @@ const failed = { const follow = ( ctx: ReturnType["ctx"], - timeoutSeconds = 3600, + options: { timeoutSeconds?: number; logs?: boolean } = {}, ) => followRun( ctx, - { runId: "run-a", runnerId: "ci", timeoutSeconds }, + { + runId: "run-a", + runnerId: "ci", + timeoutSeconds: options.timeoutSeconds ?? 3600, + logs: options.logs ?? false, + }, makeTestDeps(), ); +// The quiet default lives in followRun.quiet.test.ts; this file covers the +// --logs follow and what both modes share: settlement, unreachability, timeout. describe("followRun", () => { - it("prints the run's logs and reports it passed", async () => { + it("prints the run's logs when asked for them", async () => { const { callPublicApi, ctx, streamed } = makeAuthCtx(); callPublicApi.mockImplementation( makeJournal({ @@ -33,7 +40,7 @@ describe("followRun", () => { }), ); - expect(await follow(ctx)).toBeUndefined(); + expect(await follow(ctx, { logs: true })).toBeUndefined(); expect(streamed()).toEqual(["starting", "clicked Sign in"]); expect(ctx.ui.success).toHaveBeenCalled(); @@ -47,7 +54,7 @@ describe("followRun", () => { makeJournal({ "run-logs": [], "run-status": [[passed]] }), ); - expect(await follow(ctx)).toBeUndefined(); + expect(await follow(ctx, { logs: true })).toBeUndefined(); expect(streamed()).toEqual([]); }); @@ -75,7 +82,7 @@ describe("followRun", () => { }), ); - await follow(ctx); + await follow(ctx, { logs: true }); expect(streamed()).toEqual(["expected 3 to be 4"]); }); @@ -108,7 +115,7 @@ describe("followRun", () => { }), ); - expect(await follow(ctx)).toBeUndefined(); + expect(await follow(ctx, { logs: true })).toBeUndefined(); expect(streamed()).toEqual(["starting"]); }); @@ -127,7 +134,7 @@ describe("followRun", () => { }), ); - await follow(ctx); + await follow(ctx, { logs: true }); expect(warnings().join(" ")).toContain("3999 entries of run-logs"); }); @@ -138,7 +145,7 @@ describe("followRun", () => { makeJournal({ "run-logs": [], "run-status": [[inProgress]] }), ); - const result = await follow(ctx, 3); + const result = await follow(ctx, { timeoutSeconds: 3 }); expect(result?.exitCode).toBe(6); expect(result?.error).toContain("may still be going"); @@ -155,7 +162,7 @@ describe("followRun", () => { }), ); - await follow(ctx); + await follow(ctx, { logs: true }); expect(streamedData()[0]).toMatchObject({ payload: { message: "starting" }, diff --git a/src/domains/interactiveRunner/followRun.ts b/src/domains/interactiveRunner/followRun.ts index eabdee6cf..c7e9b3b96 100644 --- a/src/domains/interactiveRunner/followRun.ts +++ b/src/domains/interactiveRunner/followRun.ts @@ -1,4 +1,6 @@ import { + type SettledRun, + findSettlement, formatRunLogLine, readRunSettlement, } from "~/core/interactiveRunner/journal.js"; @@ -19,29 +21,9 @@ import { journalReadFailure, unreachableFailure } from "./readJournal.js"; const pollIntervalMs = 1_000; -type Settlement = - | { type: "passed" } - | { type: "failed"; errorMessage: string | undefined } - | { type: "unrecognized"; status: string }; - -function findSettlement( - entries: readonly { payload: unknown }[], -): Settlement | undefined { - for (const entry of entries) { - const settlement = readRunSettlement(entry.payload); - if (settlement.type !== "settled") continue; - if (settlement.status === "passed") return { type: "passed" }; - if (settlement.status === "failed") { - return { errorMessage: settlement.errorMessage, type: "failed" }; - } - return { status: settlement.status, type: "unrecognized" }; - } - return undefined; -} - function reportSettlement( ctx: AuthCommandContext, - settlement: Settlement, + settlement: SettledRun, ): CommandResult { if (settlement.type === "passed") { ctx.ui.success(interactiveRunnerMessages.runPassed); @@ -59,10 +41,12 @@ function reportSettlement( /** * Follows a run to its end. * - * What ends the follow is an entry on `run-status`, never the logs: a run that - * prints nothing would otherwise never finish, and a run that dies mid-sentence - * would look like one still working. The logs are the output; the status is the - * answer. + * What the follow prints is `logs`'s choice: every `run-logs` line when set, + * only the run's `run-status` events — in progress, passed, failed — when not. What + * ends the follow is an entry on `run-status` either way, never the logs: a run + * that prints nothing would otherwise never finish, and a run that dies + * mid-sentence would look like one still working. The logs are the output; the + * status is the answer. * * A runner that stops answering for long enough ends the follow too, as a * failure. `run-status` cannot cover a runner killed without running its @@ -77,20 +61,28 @@ function reportSettlement( */ export async function followRun( ctx: AuthCommandContext, - options: { runId: string; runnerId: string; timeoutSeconds: number }, + options: { + logs: boolean; + runId: string; + runnerId: string; + timeoutSeconds: number; + }, deps: InteractiveRunnerDeps, ): Promise { - const readLogs = createJournalCursor(ctx, options.runnerId, { - runId: options.runId, - stream: "run-logs", - }); + const readLogs = options.logs + ? createJournalCursor(ctx, options.runnerId, { + runId: options.runId, + stream: "run-logs", + }) + : undefined; const readStatus = createJournalCursor(ctx, options.runnerId, { runId: options.runId, stream: "run-status", }); const unreachable = createUnreachableBudget(pollIntervalMs); - const printLogs = async (): Promise => { + const printLogs = async (): Promise => { + if (readLogs === undefined) return undefined; const logs = await readLogs(); if (logs.type !== "entries") return logs; for (const entry of logs.entries) { @@ -99,6 +91,19 @@ export async function followRun( return logs; }; + // The runner may write `in-progress` again (a heartbeat, a retry); the quiet + // follow reports it once. + let progressReported = false; + const printProgress = (entries: readonly { payload: unknown }[]): void => { + if (options.logs || progressReported) return; + const entry = entries.find( + (e) => readRunSettlement(e.payload).type === "in-progress", + ); + if (entry === undefined) return; + progressReported = true; + ctx.ui.stream(entry, interactiveRunnerMessages.runInProgress); + }; + // Polls rather than a clock: the loop sleeps a known interval between reads, // so counting them bounds the follow without making it depend on wall time. const maxPolls = Math.max( @@ -108,15 +113,16 @@ export async function followRun( for (let poll = 1; ; poll++) { const logs = await printLogs(); - if (logs.type === "failed") return journalReadFailure(logs); + if (logs?.type === "failed") return journalReadFailure(logs); - const status = logs.type === "unreachable" ? logs : await readStatus(); + const status = logs?.type === "unreachable" ? logs : await readStatus(); if (status.type === "failed") return journalReadFailure(status); - if (logs.type === "unreachable" || status.type === "unreachable") { + if (status.type === "unreachable") { if (unreachable.exhausted()) return { ...unreachableFailure }; } else { unreachable.reset(); + printProgress(status.entries); const settlement = findSettlement(status.entries); if (settlement !== undefined) { // Read the logs once more before reporting: the settling status entry and diff --git a/src/domains/interactiveRunner/runFlow.follow.test.ts b/src/domains/interactiveRunner/runFlow.follow.test.ts new file mode 100644 index 000000000..8b189be4b --- /dev/null +++ b/src/domains/interactiveRunner/runFlow.follow.test.ts @@ -0,0 +1,67 @@ +import { describe, expect, it } from "bun:test"; + +import { handleRunnerRun } from "./runFlow.js"; +import { makeAuthCtx, makeTestDeps } from "./deps.testUtils.js"; +import { makeJournal } from "./journal.testUtils.js"; + +const submitted = { outcome: "submitted" as const, runId: "run-a" }; + +const runFollowing = ( + ctx: ReturnType["ctx"], + options: { follow?: boolean; timeout?: string; logs?: boolean } = {}, +) => + handleRunnerRun( + ctx, + { + entryPoint: "flow.ts", + follow: options.follow ?? true, + runner: "ci", + timeout: options.timeout ?? "1", + logs: options.logs ?? false, + }, + makeTestDeps(), + ); + +describe("handleRunnerRun --follow", () => { + it("refuses a --timeout that is not a positive number of seconds", async () => { + const { callPublicApi, ctx } = makeAuthCtx(); + + const result = await runFollowing(ctx, { timeout: "0" }); + + expect(result?.exitCode).toBe(2); + expect(callPublicApi).not.toHaveBeenCalled(); + }); + + // Following puts the run's journal entries on stdout, so the submitted run goes + // to stderr instead: two differently shaped objects on one stream would leave a + // reader sniffing keys to tell which lines are log entries. + it("announces the submitted run as a diagnostic when following", async () => { + const { callPublicApi, ctx, outputs } = makeAuthCtx(); + callPublicApi + .mockResolvedValueOnce({ ok: true, value: submitted }) + .mockImplementation(makeJournal({})); + + await runFollowing(ctx); + + expect(ctx.ui.info).toHaveBeenCalledWith(expect.stringContaining("run-a")); + expect(outputs()).toEqual([]); + }); + + // --logs only chooses what a follow prints, so alone it can only mean + // "follow, with the logs". + it("follows when --logs is given without --follow", async () => { + const { callPublicApi, ctx } = makeAuthCtx(); + callPublicApi + .mockResolvedValueOnce({ ok: true, value: submitted }) + .mockImplementation( + makeJournal({ + "run-status": [[{ runId: "run-a", status: "passed" }]], + }), + ); + + const result = await runFollowing(ctx, { follow: false, logs: true }); + + expect(result).toBeUndefined(); + expect(ctx.ui.success).toHaveBeenCalled(); + }); +}); diff --git a/src/domains/interactiveRunner/runFlow.test.ts b/src/domains/interactiveRunner/runFlow.test.ts index c97ddd0a7..d1d8db2b1 100644 --- a/src/domains/interactiveRunner/runFlow.test.ts +++ b/src/domains/interactiveRunner/runFlow.test.ts @@ -24,6 +24,7 @@ async function runWith( follow: false, runner: "ci", timeout: undefined, + logs: false, }, makeTestDeps(), ); @@ -66,6 +67,7 @@ describe("handleRunnerRun", () => { follow: false, runner: "ci", timeout: undefined, + logs: false, }, makeTestDeps(), ); @@ -85,6 +87,7 @@ describe("handleRunnerRun", () => { follow: false, runner: "ci", timeout: undefined, + logs: false, }, makeTestDeps({ collectRunFiles: async () => ({ "flow.ts": "export default {};" }), @@ -137,6 +140,7 @@ describe("handleRunnerRun", () => { follow: false, runner: undefined, timeout: undefined, + logs: false, }, deps, ); @@ -146,47 +150,6 @@ describe("handleRunnerRun", () => { expect(await deps.store.readDefaultRunnerId()).toBeUndefined(); }); - it("refuses a --timeout that is not a positive number of seconds", async () => { - const { callPublicApi, ctx } = makeAuthCtx(); - - const result = await handleRunnerRun( - ctx, - { entryPoint: "flow.ts", follow: true, runner: "ci", timeout: "0" }, - makeTestDeps(), - ); - - expect(result?.exitCode).toBe(2); - expect(callPublicApi).not.toHaveBeenCalled(); - }); - - // Following puts the run's journal entries on stdout, so the submitted run goes - // to stderr instead: two differently shaped objects on one stream would leave a - // reader sniffing keys to tell which lines are log entries. - it("announces the submitted run as a diagnostic when following", async () => { - const { callPublicApi, ctx, outputs } = makeAuthCtx(); - callPublicApi - .mockResolvedValueOnce({ ok: true, value: submitted }) - .mockResolvedValue({ - ok: true, - value: { - entries: [], - hasUnsearchedHistory: false, - nextSequence: 1, - oldestAvailableSequence: 1, - outcome: "read", - }, - }); - - await handleRunnerRun( - ctx, - { entryPoint: "flow.ts", follow: true, runner: "ci", timeout: "1" }, - makeTestDeps(), - ); - - expect(ctx.ui.info).toHaveBeenCalledWith(expect.stringContaining("run-a")); - expect(outputs()).toEqual([]); - }); - it("announces the runner it had to launch, naming it", async () => { const { callPublicApi, ctx } = makeAuthCtx(); callPublicApi @@ -208,6 +171,7 @@ describe("handleRunnerRun", () => { follow: false, runner: undefined, timeout: undefined, + logs: false, }, makeTestDeps(), ); @@ -239,6 +203,7 @@ describe("handleRunnerRun", () => { follow: false, runner: "ci", timeout: undefined, + logs: false, }, makeTestDeps(), ); diff --git a/src/domains/interactiveRunner/runFlow.ts b/src/domains/interactiveRunner/runFlow.ts index 2802c07ec..cf3d4188b 100644 --- a/src/domains/interactiveRunner/runFlow.ts +++ b/src/domains/interactiveRunner/runFlow.ts @@ -25,6 +25,7 @@ export async function handleRunnerRun( options: { entryPoint: string; follow: boolean; + logs: boolean; runner: string | undefined; timeout: string | undefined; }, @@ -89,7 +90,10 @@ export async function handleRunnerRun( }; case "submitted": { const runId = result.value.runId; - if (!options.follow) { + // --logs implies --follow: it only chooses what a follow prints, so + // alone it can only mean "follow, with the logs". + const follow = options.follow || options.logs; + if (!follow) { ctx.ui.output( { runId, runnerId: resolved.runnerId }, interactiveRunnerMessages.runSubmitted(runId), @@ -104,6 +108,7 @@ export async function handleRunnerRun( return followRun( ctx, { + logs: options.logs, runId, runnerId: resolved.runnerId, timeoutSeconds: timeout.seconds, From f81290578e8ac2c61423b4bd8592e830610747d5 Mon Sep 17 00:00:00 2001 From: Goran Gajic Date: Thu, 13 Aug 2026 15:54:02 +0200 Subject: [PATCH 2/4] feat(runner): mirror run-events and recorder streams into run --follow --run-events follows the run's progress events, filtered by runId. --recorder-events follows the recorder stream, which carries no runId (NOVA-1546), so the follow anchors at the stream's current end before submitting: a just-launched runner anchors at zero without a read, a reused one is retried on the follow's unreachable grace and fails the command before anything is billed if it never answers. Both flags print JSON lines and imply --follow. NOVA-1544 --- .changeset/quiet-runner-follow.md | 2 +- skills/qawolf-cli/references/runner.md | 15 +- src/commands/__snapshots__/help.test.ts.snap | 6 + src/commands/runner/run.register.ts | 14 ++ .../interactiveRunner/followPrinters.ts | 128 +++++++++++++ .../followRun.events.test.ts | 82 ++++++++ .../interactiveRunner/followRun.quiet.test.ts | 9 +- .../interactiveRunner/followRun.test.ts | 11 +- src/domains/interactiveRunner/followRun.ts | 68 ++++--- .../interactiveRunner/journalCursor.ts | 22 +++ .../interactiveRunner/runFlow.follow.test.ts | 181 +++++++++++++++++- src/domains/interactiveRunner/runFlow.test.ts | 12 ++ src/domains/interactiveRunner/runFlow.ts | 22 ++- 13 files changed, 516 insertions(+), 56 deletions(-) create mode 100644 src/domains/interactiveRunner/followPrinters.ts create mode 100644 src/domains/interactiveRunner/followRun.events.test.ts diff --git a/.changeset/quiet-runner-follow.md b/.changeset/quiet-runner-follow.md index 24595298e..e3fbbaf73 100644 --- a/.changeset/quiet-runner-follow.md +++ b/.changeset/quiet-runner-follow.md @@ -2,4 +2,4 @@ "@qawolf/cli": minor --- -`qawolf runner run --follow` now reports only the run's status — an "in progress" line, then whether it passed or failed — instead of streaming every log line the run produces. The full log stream is available behind the new `--logs` flag, which implies `--follow`. Anything parsing a followed run's stdout should expect status entries by default and pass `--logs` to keep receiving log lines. +`qawolf runner run --follow` now reports only the run's status — an "in progress" line, then whether it passed or failed — instead of streaming every log line the run produces. The full log stream is available behind the new `--logs` flag, and two more flags mirror further streams into the follow as JSON lines: `--run-events` for the run's progress events and `--recorder-events` for the browser actions the runner records from submission on. Each stream flag implies `--follow`. Anything parsing a followed run's stdout should expect at most one in-progress status entry by default and read the outcome from the exit code; pass `--logs` to keep receiving log lines, and follow one stream flag at a time when parsing — combined mirrors interleave without a stream label. diff --git a/skills/qawolf-cli/references/runner.md b/skills/qawolf-cli/references/runner.md index e884520e8..f90b96950 100644 --- a/skills/qawolf-cli/references/runner.md +++ b/skills/qawolf-cli/references/runner.md @@ -168,14 +168,21 @@ not in that answer**, it is in the `run-status` stream, whose entries carry **Pass `--follow` to `run` and let it wait for you.** It reports the run's status — in progress, then passed or failed — and ends on the settled status. -Exit code `1` means the run did not pass. Add `--logs` to also stream every -log line the run produces; the follow still ends on the status, never on the -logs, so a run that prints nothing still terminates the follow and a run that -dies mid-sentence still reports how. +Exit code `1` means the run did not pass. Three flags mirror more streams into +the follow, and each implies `--follow` on its own: `--logs` streams every log +line the run produces, `--run-events` streams the run's progress events as JSON +lines, and `--recorder-events` streams the browser actions the runner records +as JSON lines — the recorder is runner-wide rather than run-scoped, so that one +carries what is recorded from submission on. Whatever mirrors are on, the +follow still ends on the status, never on them, so a run that prints nothing +still terminates the follow and a run that dies mid-sentence still reports how. +Combining mirror flags interleaves their lines with nothing saying which stream +a line came from — fine for eyeballs; when parsing, follow one stream at a time. ```sh qawolf runner run flows/checkout.flow.ts --follow qawolf runner run flows/checkout.flow.ts --follow --logs +qawolf runner run flows/checkout.flow.ts --follow --recorder-events ``` If you would rather submit and come back later, note that `--follow` on `events` diff --git a/src/commands/__snapshots__/help.test.ts.snap b/src/commands/__snapshots__/help.test.ts.snap index 24b077a63..82b8ceb91 100644 --- a/src/commands/__snapshots__/help.test.ts.snap +++ b/src/commands/__snapshots__/help.test.ts.snap @@ -332,6 +332,12 @@ Options: then passed or failed (default: false) --logs Stream every log line the run produces while following. Implies --follow (default: false) + --run-events Stream the run's progress events as JSON lines while + following. Implies --follow (default: false) + --recorder-events Stream the browser actions the runner records as JSON + lines while following, from submission on: the recorder + is runner-wide, not run-scoped. Implies --follow + (default: false) --runner Runner to target. Defaults to QAWOLF_RUNNER_ID, then this directory's stored runner --timeout Give up following after this long. Following keeps the diff --git a/src/commands/runner/run.register.ts b/src/commands/runner/run.register.ts index 253570ec0..8a36545eb 100644 --- a/src/commands/runner/run.register.ts +++ b/src/commands/runner/run.register.ts @@ -25,6 +25,8 @@ Examples: type RunFlags = { follow: boolean; logs: boolean; + recorderEvents: boolean; + runEvents: boolean; runner?: string; timeout: string; }; @@ -58,6 +60,16 @@ export function registerRunnerRunCommands( "Stream every log line the run produces while following. Implies --follow", false, ) + .option( + "--run-events", + "Stream the run's progress events as JSON lines while following. Implies --follow", + false, + ) + .option( + "--recorder-events", + "Stream the browser actions the runner records as JSON lines while following, from submission on: the recorder is runner-wide, not run-scoped. Implies --follow", + false, + ) .option("--runner ", runnerFlagDescription) .option( "--timeout ", @@ -73,6 +85,8 @@ export function registerRunnerRunCommands( entryPoint: file, follow: opts.follow, logs: opts.logs, + recorderEvents: opts.recorderEvents, + runEvents: opts.runEvents, runner: opts.runner, timeout: opts.timeout, }, diff --git a/src/domains/interactiveRunner/followPrinters.ts b/src/domains/interactiveRunner/followPrinters.ts new file mode 100644 index 000000000..a7420876d --- /dev/null +++ b/src/domains/interactiveRunner/followPrinters.ts @@ -0,0 +1,128 @@ +import { formatRunLogLine } from "~/core/interactiveRunner/journal.js"; +import type { AuthCommandContext } from "~/shell/commandContext.js"; + +import { + type CursorRead, + createPrintingCursor, + createUnreachableBudget, +} from "./journalCursor.js"; +import { + journalReadFailure, + readJournal, + unreachableFailure, +} from "./readJournal.js"; + +const anchorPollIntervalMs = 1_000; + +type RecorderAnchor = + | { ok: true; sinceSequence: number } + | { ok: false; failure: ReturnType }; + +/** + * Where "this run's recorder events" begin: the recorder journal's current end. + * Taken before the run is submitted, so the anchor cannot sit past the run's + * first events. A runner this command just launched has a provably empty + * journal, so asking it would only wait out its boot for a knowable answer; + * only a reused runner is read. + * + * TODO NOVA-1546: the anchor exists because recorder payloads carry no runId; + * once the platform stamps them, a run filter replaces all of this. + */ +export async function resolveRecorderAnchor( + ctx: AuthCommandContext, + resolved: { runnerId: string; type: "launched" | "resolved" }, + deps: { sleep: (ms: number) => Promise }, +): Promise { + if (resolved.type === "launched") return { ok: true, sinceSequence: 0 }; + return anchorRecorderCursor(ctx, resolved.runnerId, deps); +} + +/** + * An unreachable runner is retried on the follow's own grace, never guessed at: + * unreachable can mean a reused runner too busy to answer, and anchoring one at + * zero would replay its whole recorder history as this run's actions. A runner + * that never answers fails the command here, before anything is submitted and + * billed. + */ +async function anchorRecorderCursor( + ctx: AuthCommandContext, + runnerId: string, + deps: { sleep: (ms: number) => Promise }, +): Promise { + const unreachable = createUnreachableBudget(anchorPollIntervalMs); + for (;;) { + const anchor = await readJournal(ctx, runnerId, { + stream: "recorder", + tail: 1, + }); + if (anchor.type === "read") { + return { ok: true, sinceSequence: anchor.value.nextSequence }; + } + if (anchor.type === "failed") { + return { failure: journalReadFailure(anchor), ok: false }; + } + if (unreachable.exhausted()) { + return { failure: { ...unreachableFailure }, ok: false }; + } + await deps.sleep(anchorPollIntervalMs); + } +} + +export type FollowStreamOptions = { + logs: boolean; + /** + * Where in the `recorder` stream this run's events begin, or undefined to not + * follow it. An anchor rather than a run filter, because recorder entries + * carry no `runId` — the recorder outlives runs, so "this run's recorder + * events" can only mean "recorded after this point". + */ + recorderSinceSequence: number | undefined; + runEvents: boolean; + runId: string; + runnerId: string; +}; + +/** + * The mirror streams a follow prints beside `run-status`, one printing cursor + * per stream a flag asked for. Log lines print as their message; the event + * streams print each payload as one JSON line, the same rendering + * `qawolf runner events` gives them. + */ +export function createFollowPrinters( + ctx: AuthCommandContext, + options: FollowStreamOptions, +): (() => Promise)[] { + const jsonLine = (payload: unknown) => JSON.stringify(payload); + const printers: (() => Promise)[] = []; + if (options.logs) { + printers.push( + createPrintingCursor( + ctx, + options.runnerId, + { runId: options.runId, stream: "run-logs" }, + formatRunLogLine, + ), + ); + } + if (options.runEvents) { + printers.push( + createPrintingCursor( + ctx, + options.runnerId, + { runId: options.runId, stream: "run-events" }, + jsonLine, + ), + ); + } + if (options.recorderSinceSequence !== undefined) { + printers.push( + createPrintingCursor( + ctx, + options.runnerId, + { sinceSequence: options.recorderSinceSequence, stream: "recorder" }, + jsonLine, + ), + ); + } + return printers; +} diff --git a/src/domains/interactiveRunner/followRun.events.test.ts b/src/domains/interactiveRunner/followRun.events.test.ts new file mode 100644 index 000000000..787c7584e --- /dev/null +++ b/src/domains/interactiveRunner/followRun.events.test.ts @@ -0,0 +1,82 @@ +import { describe, expect, it } from "bun:test"; + +import { followRun } from "./followRun.js"; +import { makeAuthCtx, makeTestDeps } from "./deps.testUtils.js"; +import { makeJournal } from "./journal.testUtils.js"; + +const inProgress = { runId: "run-a", status: "in-progress" }; +const passed = { runId: "run-a", status: "passed" }; + +const follow = ( + ctx: ReturnType["ctx"], + options: { recorderSinceSequence?: number; runEvents?: boolean } = {}, +) => + followRun( + ctx, + { + logs: false, + recorderSinceSequence: options.recorderSinceSequence, + runEvents: options.runEvents ?? false, + runId: "run-a", + runnerId: "ci", + timeoutSeconds: 3600, + }, + makeTestDeps(), + ); + +describe("followRun mirror event streams", () => { + // JSON lines, not prose: an event payload has no one-line rendering of its + // own, and JSON is what `qawolf runner events` prints for the same entry. The + // in-progress line stays out for the same reason: prose among JSON lines + // hurts a parser. + it("prints run events as JSON lines, without the in-progress prose", async () => { + const progress = { + filePath: "flow.ts", + runId: "run-a", + type: "file-completed", + }; + const { callPublicApi, ctx, streamed } = makeAuthCtx(); + callPublicApi.mockImplementation( + makeJournal({ + "run-events": [[progress]], + "run-status": [[inProgress], [passed]], + }), + ); + + expect(await follow(ctx, { runEvents: true })).toBeUndefined(); + + expect(streamed()).toEqual([JSON.stringify(progress)]); + expect(ctx.ui.success).toHaveBeenCalled(); + }); + + it("prints recorder events as JSON lines", async () => { + const click = { locator: "getByRole('button')", type: "click" }; + const { callPublicApi, ctx, streamed } = makeAuthCtx(); + callPublicApi.mockImplementation( + makeJournal({ recorder: [[click]], "run-status": [[passed]] }), + ); + + expect(await follow(ctx, { recorderSinceSequence: 41 })).toBeUndefined(); + expect(streamed()).toEqual([JSON.stringify(click)]); + }); + + // Recorder entries carry no runId, so the anchor is the only thing keeping a + // reused runner's whole recorder history out of the follow. + it("reads the recorder only after its anchor", async () => { + const { callPublicApi, ctx } = makeAuthCtx(); + callPublicApi.mockImplementation( + makeJournal({ recorder: [], "run-status": [[passed]] }), + ); + + await follow(ctx, { recorderSinceSequence: 41 }); + + const recorderReads = callPublicApi.mock.calls.filter( + ([, input]) => (input as { stream: string }).stream === "recorder", + ); + expect(recorderReads.length).toBeGreaterThan(0); + expect(recorderReads[0]?.[1]).toMatchObject({ sinceSequence: 41 }); + // Unfiltered by run, deliberately: a runId filter on a stream whose entries + // carry none would silently match nothing. + expect(recorderReads[0]?.[1]).not.toHaveProperty("runId"); + }); +}); diff --git a/src/domains/interactiveRunner/followRun.quiet.test.ts b/src/domains/interactiveRunner/followRun.quiet.test.ts index 5af420d51..f59c1b91b 100644 --- a/src/domains/interactiveRunner/followRun.quiet.test.ts +++ b/src/domains/interactiveRunner/followRun.quiet.test.ts @@ -10,7 +10,14 @@ const passed = { runId: "run-a", status: "passed" }; const follow = (ctx: ReturnType["ctx"]) => followRun( ctx, - { logs: false, runId: "run-a", runnerId: "ci", timeoutSeconds: 3600 }, + { + logs: false, + recorderSinceSequence: undefined, + runEvents: false, + runId: "run-a", + runnerId: "ci", + timeoutSeconds: 3600, + }, makeTestDeps(), ); diff --git a/src/domains/interactiveRunner/followRun.test.ts b/src/domains/interactiveRunner/followRun.test.ts index 5143fe4cf..dc2189e3f 100644 --- a/src/domains/interactiveRunner/followRun.test.ts +++ b/src/domains/interactiveRunner/followRun.test.ts @@ -15,15 +15,22 @@ const failed = { const follow = ( ctx: ReturnType["ctx"], - options: { timeoutSeconds?: number; logs?: boolean } = {}, + options: { + logs?: boolean; + recorderSinceSequence?: number; + runEvents?: boolean; + timeoutSeconds?: number; + } = {}, ) => followRun( ctx, { + logs: options.logs ?? false, + recorderSinceSequence: options.recorderSinceSequence, + runEvents: options.runEvents ?? false, runId: "run-a", runnerId: "ci", timeoutSeconds: options.timeoutSeconds ?? 3600, - logs: options.logs ?? false, }, makeTestDeps(), ); diff --git a/src/domains/interactiveRunner/followRun.ts b/src/domains/interactiveRunner/followRun.ts index c7e9b3b96..5b2d58f20 100644 --- a/src/domains/interactiveRunner/followRun.ts +++ b/src/domains/interactiveRunner/followRun.ts @@ -1,7 +1,6 @@ import { type SettledRun, findSettlement, - formatRunLogLine, readRunSettlement, } from "~/core/interactiveRunner/journal.js"; import { interactiveRunnerMessages } from "~/core/messages/index.js"; @@ -12,6 +11,10 @@ import type { import { exitCodes } from "~/shell/exit.js"; import type { InteractiveRunnerDeps } from "./deps.js"; +import { + type FollowStreamOptions, + createFollowPrinters, +} from "./followPrinters.js"; import { type CursorRead, createJournalCursor, @@ -41,12 +44,13 @@ function reportSettlement( /** * Follows a run to its end. * - * What the follow prints is `logs`'s choice: every `run-logs` line when set, - * only the run's `run-status` events — in progress, passed, failed — when not. What - * ends the follow is an entry on `run-status` either way, never the logs: a run - * that prints nothing would otherwise never finish, and a run that dies - * mid-sentence would look like one still working. The logs are the output; the - * status is the answer. + * What the follow prints is the flags' choice: only the run's `run-status` + * events — in progress, passed, failed — by default, plus whichever mirror + * streams were asked for (see {@link createFollowPrinters}). What ends the + * follow is an entry on `run-status` either way, never the mirrors: a run that + * prints nothing would otherwise never finish, and a run that dies mid-sentence + * would look like one still working. The mirrors are the output; the status is + * the answer. * * A runner that stops answering for long enough ends the follow too, as a * failure. `run-status` cannot cover a runner killed without running its @@ -61,41 +65,32 @@ function reportSettlement( */ export async function followRun( ctx: AuthCommandContext, - options: { - logs: boolean; - runId: string; - runnerId: string; - timeoutSeconds: number; - }, + options: FollowStreamOptions & { timeoutSeconds: number }, deps: InteractiveRunnerDeps, ): Promise { - const readLogs = options.logs - ? createJournalCursor(ctx, options.runnerId, { - runId: options.runId, - stream: "run-logs", - }) - : undefined; + const printers = createFollowPrinters(ctx, options); const readStatus = createJournalCursor(ctx, options.runnerId, { runId: options.runId, stream: "run-status", }); const unreachable = createUnreachableBudget(pollIntervalMs); - const printLogs = async (): Promise => { - if (readLogs === undefined) return undefined; - const logs = await readLogs(); - if (logs.type !== "entries") return logs; - for (const entry of logs.entries) { - ctx.ui.stream(entry, formatRunLogLine(entry.payload)); + /** Undefined when every printer read cleanly; the interrupting read if not. */ + const printAll = async (): Promise => { + for (const print of printers) { + const window = await print(); + if (window.type !== "entries") return window; } - return logs; + return undefined; }; - // The runner may write `in-progress` again (a heartbeat, a retry); the quiet + // The in-progress line is for the otherwise-silent follow: any mirror stream + // already shows life, and prose among its JSON lines would hurt a parser. The + // runner may also write `in-progress` again (a heartbeat, a retry); the quiet // follow reports it once. let progressReported = false; const printProgress = (entries: readonly { payload: unknown }[]): void => { - if (options.logs || progressReported) return; + if (printers.length > 0 || progressReported) return; const entry = entries.find( (e) => readRunSettlement(e.payload).type === "in-progress", ); @@ -112,10 +107,11 @@ export async function followRun( ); for (let poll = 1; ; poll++) { - const logs = await printLogs(); - if (logs?.type === "failed") return journalReadFailure(logs); + const interrupted = await printAll(); + if (interrupted?.type === "failed") return journalReadFailure(interrupted); - const status = logs?.type === "unreachable" ? logs : await readStatus(); + const status = + interrupted?.type === "unreachable" ? interrupted : await readStatus(); if (status.type === "failed") return journalReadFailure(status); if (status.type === "unreachable") { @@ -125,11 +121,11 @@ export async function followRun( printProgress(status.entries); const settlement = findSettlement(status.entries); if (settlement !== undefined) { - // Read the logs once more before reporting: the settling status entry and - // the run's last lines are appended to different streams, so the status can - // win the race and stopping here would cut the output off short of the very - // failure being reported. - await printLogs(); + // Read the mirrors once more before reporting: the settling status entry + // and the run's last lines are appended to different streams, so the + // status can win the race and stopping here would cut the output off + // short of the very failure being reported. + await printAll(); return reportSettlement(ctx, settlement); } } diff --git a/src/domains/interactiveRunner/journalCursor.ts b/src/domains/interactiveRunner/journalCursor.ts index ef506db73..27fcc9403 100644 --- a/src/domains/interactiveRunner/journalCursor.ts +++ b/src/domains/interactiveRunner/journalCursor.ts @@ -67,6 +67,28 @@ export function createJournalCursor( }; } +/** + * A cursor that prints what it reads: every new entry is streamed to the UI, + * the whole entry as the data and `format`'s rendering of its payload as the + * line. + */ +export function createPrintingCursor( + ctx: AuthCommandContext, + runnerId: string, + request: JournalRequest, + format: (payload: unknown) => string, +): () => Promise { + const read = createJournalCursor(ctx, runnerId, request); + return async () => { + const window = await read(); + if (window.type !== "entries") return window; + for (const entry of window.entries) { + ctx.ui.stream(entry, format(entry.payload)); + } + return window; + }; +} + /** * How long a follow keeps asking a runner that will not answer. * diff --git a/src/domains/interactiveRunner/runFlow.follow.test.ts b/src/domains/interactiveRunner/runFlow.follow.test.ts index 8b189be4b..52dae5564 100644 --- a/src/domains/interactiveRunner/runFlow.follow.test.ts +++ b/src/domains/interactiveRunner/runFlow.follow.test.ts @@ -8,20 +8,36 @@ const submitted = { outcome: "submitted" as const, runId: "run-a" }; const runFollowing = ( ctx: ReturnType["ctx"], - options: { follow?: boolean; timeout?: string; logs?: boolean } = {}, + options: { + follow?: boolean; + launch?: boolean; + logs?: boolean; + recorderEvents?: boolean; + runEvents?: boolean; + timeout?: string; + } = {}, ) => handleRunnerRun( ctx, { entryPoint: "flow.ts", follow: options.follow ?? true, - runner: "ci", - timeout: options.timeout ?? "1", logs: options.logs ?? false, + recorderEvents: options.recorderEvents ?? false, + runEvents: options.runEvents ?? false, + runner: options.launch ? undefined : "ci", + timeout: options.timeout ?? "1", }, makeTestDeps(), ); +const wasSubmitted = ( + callPublicApi: ReturnType["callPublicApi"], +) => + callPublicApi.mock.calls.some( + ([, input]) => (input as { entryPointPath?: string }).entryPointPath, + ); + describe("handleRunnerRun --follow", () => { it("refuses a --timeout that is not a positive number of seconds", async () => { const { callPublicApi, ctx } = makeAuthCtx(); @@ -47,11 +63,48 @@ describe("handleRunnerRun --follow", () => { expect(outputs()).toEqual([]); }); - // --logs only chooses what a follow prints, so alone it can only mean - // "follow, with the logs". - it("follows when --logs is given without --follow", async () => { + // A stream flag only chooses what a follow prints, so alone it can only mean + // "follow, with that stream". + for (const streamFlag of ["logs", "recorderEvents", "runEvents"] as const) { + it(`follows when --${streamFlag} is given without --follow`, async () => { + const { callPublicApi, ctx } = makeAuthCtx(); + // Dispatched on the input rather than call order: --recorder-events reads + // its anchor before the submission happens. + const journal = makeJournal({ + "run-status": [[{ runId: "run-a", status: "passed" }]], + }); + callPublicApi.mockImplementation((contract, input) => + (input as { stream?: string }).stream === undefined + ? Promise.resolve({ ok: true, value: submitted }) + : journal(contract, input), + ); + + const result = await runFollowing(ctx, { + follow: false, + [streamFlag]: true, + }); + + expect(result).toBeUndefined(); + expect(ctx.ui.success).toHaveBeenCalled(); + }); + } + + // Recorder entries carry no runId, so this run's events are "everything after + // the anchor" — and an anchor taken after submission could sit past the run's + // first events. + it("anchors the recorder before submitting the run", async () => { const { callPublicApi, ctx } = makeAuthCtx(); callPublicApi + .mockResolvedValueOnce({ + ok: true, + value: { + entries: [], + hasUnsearchedHistory: false, + nextSequence: 7, + oldestAvailableSequence: 1, + outcome: "read", + }, + }) .mockResolvedValueOnce({ ok: true, value: submitted }) .mockImplementation( makeJournal({ @@ -59,9 +112,119 @@ describe("handleRunnerRun --follow", () => { }), ); - const result = await runFollowing(ctx, { follow: false, logs: true }); + await runFollowing(ctx, { recorderEvents: true }); + + expect(callPublicApi.mock.calls[0]?.[1]).toMatchObject({ + stream: "recorder", + tail: 1, + }); + const recorderFollowReads = callPublicApi.mock.calls + .slice(2) + .filter( + ([, input]) => (input as { stream?: string }).stream === "recorder", + ); + expect(recorderFollowReads[0]?.[1]).toMatchObject({ sinceSequence: 7 }); + }); + + // A runner this command just launched has a provably empty journal, so asking + // it for an anchor would only wait out its boot for a knowable answer. + it("anchors a runner it just launched at the start, without asking it", async () => { + const { callPublicApi, ctx } = makeAuthCtx(); + const journal = makeJournal({ + "run-status": [[{ runId: "run-a", status: "passed" }]], + }); + callPublicApi + .mockResolvedValueOnce({ + ok: true, + value: { + gpuAccelerated: false, + id: "cli-minted", + outcome: "launched", + runnerName: "node20WithPlaywright", + }, + }) + .mockImplementation((contract, input) => + (input as { stream?: string }).stream === undefined + ? Promise.resolve({ ok: true, value: submitted }) + : journal(contract, input), + ); + + await runFollowing(ctx, { launch: true, recorderEvents: true }); + + const anchorReads = callPublicApi.mock.calls.filter( + ([, input]) => (input as { tail?: number }).tail === 1, + ); + expect(anchorReads).toEqual([]); + const recorderReads = callPublicApi.mock.calls.filter( + ([, input]) => (input as { stream?: string }).stream === "recorder", + ); + expect(recorderReads[0]?.[1]).toMatchObject({ sinceSequence: 0 }); + }); + + // Unreachable can mean a reused runner too busy to answer, and guessing an + // anchor of zero would replay its whole recorder history as this run's + // actions. The anchor waits like the follow does. + it("keeps asking a reused runner for its anchor until it answers", async () => { + const { callPublicApi, ctx } = makeAuthCtx(); + const journal = makeJournal({ + "run-status": [[{ runId: "run-a", status: "passed" }]], + }); + let anchorReads = 0; + callPublicApi.mockImplementation((contract, input) => { + const request = input as { stream?: string; tail?: number }; + if (request.tail === 1) { + anchorReads++; + return Promise.resolve( + anchorReads === 1 + ? { ok: true, value: { outcome: "runner-unreachable" } } + : { + ok: true, + value: { + entries: [], + hasUnsearchedHistory: false, + nextSequence: 7, + oldestAvailableSequence: 1, + outcome: "read", + }, + }, + ); + } + if (request.stream === undefined) { + return Promise.resolve({ ok: true, value: submitted }); + } + return journal(contract, input); + }); + + expect(await runFollowing(ctx, { recorderEvents: true })).toBeUndefined(); + expect(anchorReads).toBe(2); + }); + + // Nothing has been submitted or billed yet at anchor time, so a runner that + // will not answer fails the command rather than starting a run whose recorder + // follow is already broken. + it("fails without submitting when a reused runner never answers its anchor", async () => { + const { callPublicApi, ctx } = makeAuthCtx(); + callPublicApi.mockResolvedValue({ + ok: true, + value: { outcome: "runner-unreachable" }, + }); + + const result = await runFollowing(ctx, { recorderEvents: true }); + + expect(result?.exitCode).toBe(4); + expect(wasSubmitted(callPublicApi)).toBe(false); + }); + + it("fails without submitting when the anchor read fails outright", async () => { + const { callPublicApi, ctx } = makeAuthCtx(); + callPublicApi.mockResolvedValue({ + error: "QA Wolf API runner.readJournal request failed (HTTP 500).", + ok: false, + }); + + const result = await runFollowing(ctx, { recorderEvents: true }); - expect(result).toBeUndefined(); - expect(ctx.ui.success).toHaveBeenCalled(); + expect(result?.error).toContain("readJournal"); + expect(wasSubmitted(callPublicApi)).toBe(false); }); }); diff --git a/src/domains/interactiveRunner/runFlow.test.ts b/src/domains/interactiveRunner/runFlow.test.ts index d1d8db2b1..f11640ac6 100644 --- a/src/domains/interactiveRunner/runFlow.test.ts +++ b/src/domains/interactiveRunner/runFlow.test.ts @@ -25,6 +25,8 @@ async function runWith( runner: "ci", timeout: undefined, logs: false, + recorderEvents: false, + runEvents: false, }, makeTestDeps(), ); @@ -68,6 +70,8 @@ describe("handleRunnerRun", () => { runner: "ci", timeout: undefined, logs: false, + recorderEvents: false, + runEvents: false, }, makeTestDeps(), ); @@ -88,6 +92,8 @@ describe("handleRunnerRun", () => { runner: "ci", timeout: undefined, logs: false, + recorderEvents: false, + runEvents: false, }, makeTestDeps({ collectRunFiles: async () => ({ "flow.ts": "export default {};" }), @@ -141,6 +147,8 @@ describe("handleRunnerRun", () => { runner: undefined, timeout: undefined, logs: false, + recorderEvents: false, + runEvents: false, }, deps, ); @@ -172,6 +180,8 @@ describe("handleRunnerRun", () => { runner: undefined, timeout: undefined, logs: false, + recorderEvents: false, + runEvents: false, }, makeTestDeps(), ); @@ -204,6 +214,8 @@ describe("handleRunnerRun", () => { runner: "ci", timeout: undefined, logs: false, + recorderEvents: false, + runEvents: false, }, makeTestDeps(), ); diff --git a/src/domains/interactiveRunner/runFlow.ts b/src/domains/interactiveRunner/runFlow.ts index cf3d4188b..e215e666b 100644 --- a/src/domains/interactiveRunner/runFlow.ts +++ b/src/domains/interactiveRunner/runFlow.ts @@ -16,6 +16,7 @@ import { failureFields } from "~/shell/platform/requestWithRetry.js"; import { collectRunFiles } from "./collectFiles.js"; import type { InteractiveRunnerDeps } from "./deps.js"; +import { resolveRecorderAnchor } from "./followPrinters.js"; import { followRun } from "./followRun.js"; import { announceRunner, resolveRunner } from "./resolveRunner.js"; import { runnerCallOptions } from "./runnerCallOptions.js"; @@ -26,6 +27,8 @@ export async function handleRunnerRun( entryPoint: string; follow: boolean; logs: boolean; + recorderEvents: boolean; + runEvents: boolean; runner: string | undefined; timeout: string | undefined; }, @@ -63,6 +66,13 @@ export async function handleRunnerRun( } announceRunner(ctx, resolved); + let recorderSinceSequence: number | undefined; + if (options.recorderEvents) { + const anchor = await resolveRecorderAnchor(ctx, resolved, deps); + if (!anchor.ok) return { ...anchor.failure }; + recorderSinceSequence = anchor.sinceSequence; + } + const result = await ctx.platformClient.callPublicApi( publicContractsV1.runner.runFlow, { entryPointPath, files, id: resolved.runnerId }, @@ -90,9 +100,13 @@ export async function handleRunnerRun( }; case "submitted": { const runId = result.value.runId; - // --logs implies --follow: it only chooses what a follow prints, so - // alone it can only mean "follow, with the logs". - const follow = options.follow || options.logs; + // The stream flags imply --follow: each only chooses what a follow + // prints, so alone it can only mean "follow, with that stream". + const follow = + options.follow || + options.logs || + options.runEvents || + options.recorderEvents; if (!follow) { ctx.ui.output( { runId, runnerId: resolved.runnerId }, @@ -109,6 +123,8 @@ export async function handleRunnerRun( ctx, { logs: options.logs, + recorderSinceSequence, + runEvents: options.runEvents, runId, runnerId: resolved.runnerId, timeoutSeconds: timeout.seconds, From d8acec388401e8c3f4fb8cc4b72d91f25020747a Mon Sep 17 00:00:00 2001 From: Goran Gajic Date: Thu, 13 Aug 2026 18:32:41 +0200 Subject: [PATCH 3/4] docs(runner): recorder-events start at a pre-submission anchor --- .changeset/quiet-runner-follow.md | 2 +- skills/qawolf-cli/references/runner.md | 2 +- src/commands/__snapshots__/help.test.ts.snap | 6 +++--- src/commands/runner/run.register.ts | 2 +- 4 files changed, 6 insertions(+), 6 deletions(-) diff --git a/.changeset/quiet-runner-follow.md b/.changeset/quiet-runner-follow.md index e3fbbaf73..2ae4a6015 100644 --- a/.changeset/quiet-runner-follow.md +++ b/.changeset/quiet-runner-follow.md @@ -2,4 +2,4 @@ "@qawolf/cli": minor --- -`qawolf runner run --follow` now reports only the run's status — an "in progress" line, then whether it passed or failed — instead of streaming every log line the run produces. The full log stream is available behind the new `--logs` flag, and two more flags mirror further streams into the follow as JSON lines: `--run-events` for the run's progress events and `--recorder-events` for the browser actions the runner records from submission on. Each stream flag implies `--follow`. Anything parsing a followed run's stdout should expect at most one in-progress status entry by default and read the outcome from the exit code; pass `--logs` to keep receiving log lines, and follow one stream flag at a time when parsing — combined mirrors interleave without a stream label. +`qawolf runner run --follow` now reports only the run's status — an "in progress" line, then whether it passed or failed — instead of streaming every log line the run produces. The full log stream is available behind the new `--logs` flag, and two more flags mirror further streams into the follow as JSON lines: `--run-events` for the run's progress events and `--recorder-events` for the browser actions the runner records after an anchor taken just before submission. Each stream flag implies `--follow`. Anything parsing a followed run's stdout should expect at most one in-progress status entry by default and read the outcome from the exit code; pass `--logs` to keep receiving log lines, and follow one stream flag at a time when parsing — combined mirrors interleave without a stream label. diff --git a/skills/qawolf-cli/references/runner.md b/skills/qawolf-cli/references/runner.md index f90b96950..5e53cff18 100644 --- a/skills/qawolf-cli/references/runner.md +++ b/skills/qawolf-cli/references/runner.md @@ -173,7 +173,7 @@ the follow, and each implies `--follow` on its own: `--logs` streams every log line the run produces, `--run-events` streams the run's progress events as JSON lines, and `--recorder-events` streams the browser actions the runner records as JSON lines — the recorder is runner-wide rather than run-scoped, so that one -carries what is recorded from submission on. Whatever mirrors are on, the +carries whatever is recorded after an anchor taken just before submission. Whatever mirrors are on, the follow still ends on the status, never on them, so a run that prints nothing still terminates the follow and a run that dies mid-sentence still reports how. Combining mirror flags interleaves their lines with nothing saying which stream diff --git a/src/commands/__snapshots__/help.test.ts.snap b/src/commands/__snapshots__/help.test.ts.snap index 82b8ceb91..099529683 100644 --- a/src/commands/__snapshots__/help.test.ts.snap +++ b/src/commands/__snapshots__/help.test.ts.snap @@ -335,9 +335,9 @@ Options: --run-events Stream the run's progress events as JSON lines while following. Implies --follow (default: false) --recorder-events Stream the browser actions the runner records as JSON - lines while following, from submission on: the recorder - is runner-wide, not run-scoped. Implies --follow - (default: false) + lines while following, from an anchor taken just before + submission: the recorder is runner-wide, not run-scoped. + Implies --follow (default: false) --runner Runner to target. Defaults to QAWOLF_RUNNER_ID, then this directory's stored runner --timeout Give up following after this long. Following keeps the diff --git a/src/commands/runner/run.register.ts b/src/commands/runner/run.register.ts index 8a36545eb..fbf523d3a 100644 --- a/src/commands/runner/run.register.ts +++ b/src/commands/runner/run.register.ts @@ -67,7 +67,7 @@ export function registerRunnerRunCommands( ) .option( "--recorder-events", - "Stream the browser actions the runner records as JSON lines while following, from submission on: the recorder is runner-wide, not run-scoped. Implies --follow", + "Stream the browser actions the runner records as JSON lines while following, from an anchor taken just before submission: the recorder is runner-wide, not run-scoped. Implies --follow", false, ) .option("--runner ", runnerFlagDescription) From a565d12e143482cc9239985b4e80c190c651d3ad Mon Sep 17 00:00:00 2001 From: Goran Gajic Date: Thu, 13 Aug 2026 18:33:44 +0200 Subject: [PATCH 4/4] fix(runner): warn when a follow's final mirror read fails The flush after settlement silently swallowed a failed read, so a followed run could exit as passed with its last output lines missing and nothing saying so. The settlement still decides the exit code: a run's outcome must not be overridden by a flush of its output. --- src/core/messages/interactiveRunner.ts | 2 ++ .../interactiveRunner/followRun.test.ts | 20 +++++++++++++++++++ src/domains/interactiveRunner/followRun.ts | 8 ++++++-- 3 files changed, 28 insertions(+), 2 deletions(-) diff --git a/src/core/messages/interactiveRunner.ts b/src/core/messages/interactiveRunner.ts index 72046ae22..d581daab0 100644 --- a/src/core/messages/interactiveRunner.ts +++ b/src/core/messages/interactiveRunner.ts @@ -46,6 +46,8 @@ export const interactiveRunnerMessages = { `No runner was given, so launched ${id} for this command. Its browser is fresh: nothing has been run on it and nothing is signed in. It bills until it is stopped or idles out, so stop it with qawolf runner stop --runner ${id} when you are done.`, followEventsTimedOut: (stream: string, seconds: number) => `Stopped following ${stream} after ${formatSeconds(seconds * 1000)}: reading keeps the runner alive and billing, so a follow does not run unbounded. Pass --timeout to wait longer, or follow again to continue.`, + followEndCutShort: + "The run settled, but the last window of its followed streams could not be read, so the output above may be missing its final lines.", followTimedOut: (runId: string, runnerId: string, seconds: number) => `Stopped following run ${runId} after ${formatSeconds(seconds * 1000)}. The run may still be going: read it with qawolf runner events run-status --run ${runId}, and stop the runner with qawolf runner stop --runner ${runnerId} when you are done. Pass --timeout to wait longer.`, missingPackageJson: diff --git a/src/domains/interactiveRunner/followRun.test.ts b/src/domains/interactiveRunner/followRun.test.ts index dc2189e3f..af334eb3d 100644 --- a/src/domains/interactiveRunner/followRun.test.ts +++ b/src/domains/interactiveRunner/followRun.test.ts @@ -146,6 +146,26 @@ describe("followRun", () => { expect(warnings().join(" ")).toContain("3999 entries of run-logs"); }); + // The settlement is known by then, so a flush of the output must not + // override the run's outcome — but silence would misreport a cut-off log. + it("warns when the final mirror read fails, and keeps the settlement", async () => { + const { callPublicApi, ctx, warnings } = makeAuthCtx(); + let logReads = 0; + const journal = makeJournal({ "run-status": [[passed]] }); + callPublicApi.mockImplementation((contract, input) => { + const stream = (input as { stream: string }).stream; + if (stream === "run-logs" && ++logReads === 2) { + return Promise.resolve({ error: "HTTP 500", ok: false }); + } + return journal(contract, input); + }); + + expect(await follow(ctx, { logs: true })).toBeUndefined(); + + expect(ctx.ui.success).toHaveBeenCalled(); + expect(warnings().join(" ")).toContain("missing its final lines"); + }); + it("gives up on a run that never settles, and says the run may still be going", async () => { const { callPublicApi, ctx } = makeAuthCtx(); callPublicApi.mockImplementation( diff --git a/src/domains/interactiveRunner/followRun.ts b/src/domains/interactiveRunner/followRun.ts index 5b2d58f20..ab576abab 100644 --- a/src/domains/interactiveRunner/followRun.ts +++ b/src/domains/interactiveRunner/followRun.ts @@ -124,8 +124,12 @@ export async function followRun( // Read the mirrors once more before reporting: the settling status entry // and the run's last lines are appended to different streams, so the // status can win the race and stopping here would cut the output off - // short of the very failure being reported. - await printAll(); + // short of the very failure being reported. A warning rather than a + // failure when this read does not answer: the settlement is known, and + // the run's outcome must not be overridden by a flush of its output. + if ((await printAll()) !== undefined) { + ctx.ui.warn(interactiveRunnerMessages.followEndCutShort); + } return reportSettlement(ctx, settlement); } }