fix: bound sf print mode and chat routing

This commit is contained in:
Mikael Hugo 2026-05-14 20:55:00 +02:00
parent b19096800b
commit 487237a32c
11 changed files with 416 additions and 48 deletions

View file

@ -145,4 +145,40 @@ describe("AgentSession custom message queueing", () => {
assert.equal(commandArgs, "");
assert.equal(agentPrompted, false);
});
it("executes_slash_command_after_input_hook_adds_route_trace_marker", async () => {
const session = await createSession();
const agent = (session as any).agent as Agent & {
prompt: (message: AgentMessage) => Promise<void>;
};
let agentPrompted = false;
let commandArgs: string | undefined;
agent.prompt = async () => {
agentPrompted = true;
};
(session as any)._extensionRunner = {
hasHandlers: (event: string) => event === "input",
emitInput: async () => ({
action: "transform",
text: "[sf-route:chat-intent:test] /queue",
images: undefined,
}),
getCommand: (name: string) =>
name === "queue"
? {
name: "queue",
handler: async (args: string) => {
commandArgs = args;
},
}
: undefined,
createCommandContext: () => ({}),
emitError: () => undefined,
};
await session.prompt("show my queue");
assert.equal(commandArgs, "");
assert.equal(agentPrompted, false);
});
});

View file

@ -179,3 +179,23 @@ test("sf src/cli.ts print-mode skips validateConfiguredModel when --model is set
"reapplyValidatedModelOnFallback must be inside the same `if (!cliFlags.model)` block as validateConfiguredModel",
);
});
test("sf src/cli.ts print-mode skips live discovery provider warmup", () => {
const registryStartupIdx = sfCliSource.indexOf(
'markStartup("ModelRegistry")',
);
assert.ok(registryStartupIdx >= 0, "missing model registry startup marker");
const warmupIdx = sfCliSource.indexOf(
"warmDiscoveryBackedProviders(",
registryStartupIdx,
);
assert.ok(warmupIdx >= 0, "missing discovery-backed provider warmup");
const guardIdx = sfCliSource.lastIndexOf(
"if (!isPrintMode && cliFlags.listModels === undefined)",
warmupIdx,
);
assert.ok(
guardIdx >= 0,
"print mode and static model listing must not run live provider discovery before producing one-shot output",
);
});

View file

@ -241,6 +241,8 @@ export interface PromptOptions {
streamingBehavior?: "steer" | "followUp";
/** Source of input for extension input event handlers. Defaults to "interactive". */
source?: InputSource;
/** Whether extension input/before-agent hooks run for this prompt. Defaults to true. */
runExtensionHooks?: boolean;
}
function isAgentAlreadyProcessingError(error: unknown): boolean {
@ -1195,6 +1197,7 @@ export class AgentSession {
*/
async prompt(text: string, options?: PromptOptions): Promise<void> {
const expandPromptTemplates = options?.expandPromptTemplates ?? true;
const runExtensionHooks = options?.runExtensionHooks ?? true;
// Handle extension commands first (execute immediately, even during streaming)
// Extension commands manage their own LLM interaction via pi.sendMessage()
@ -1209,7 +1212,7 @@ export class AgentSession {
// Emit input event for extension interception (before skill/template expansion)
let currentText = text;
let currentImages = options?.images;
if (this._extensionRunner?.hasHandlers("input")) {
if (runExtensionHooks && this._extensionRunner?.hasHandlers("input")) {
const inputResult = await this._extensionRunner.emitInput(
currentText,
currentImages,
@ -1233,6 +1236,21 @@ export class AgentSession {
return;
}
}
if (
expandPromptTemplates &&
currentText !== text &&
currentText.startsWith("[sf-route:")
) {
const end = currentText.indexOf("]");
const routedText =
end === -1 ? currentText : currentText.slice(end + 1).trim();
if (routedText.startsWith("/")) {
const handled = await this._tryExecuteExtensionCommand(routedText);
if (handled) {
return;
}
}
}
// Expand skill commands (/skill:name args) and prompt templates (/template args)
let expandedText = currentText;
@ -1332,7 +1350,7 @@ export class AgentSession {
this._pendingNextTurnMessages = [];
// Emit before_agent_start extension event
if (this._extensionRunner) {
if (runExtensionHooks && this._extensionRunner) {
const result = await this._extensionRunner.emitBeforeAgentStart(
expandedText,
currentImages,

View file

@ -0,0 +1,81 @@
import assert from "node:assert/strict";
import { test } from "vitest";
import {
PrintModeTimeoutError,
promptWithPrintTimeout,
resolvePrintModeTimeoutMs,
runPrintMode,
} from "./print-mode.js";
test("resolvePrintModeTimeoutMs_when_env_missing_returns_default_watchdog", () => {
assert.equal(resolvePrintModeTimeoutMs({}), 55_000);
});
test("resolvePrintModeTimeoutMs_when_env_zero_disables_watchdog", () => {
assert.equal(resolvePrintModeTimeoutMs({ SF_PRINT_TIMEOUT_MS: "0" }), 0);
});
test("promptWithPrintTimeout_when_prompt_never_settles_aborts_and_rejects", async () => {
let aborted = false;
const session = {
prompt: () => new Promise<void>(() => {}),
abort: async () => {
aborted = true;
},
};
await assert.rejects(
() => promptWithPrintTimeout(session as any, "say hi", undefined, 5),
PrintModeTimeoutError,
);
assert.equal(aborted, true);
});
test("promptWithPrintTimeout_when_prompt_settles_clears_watchdog", async () => {
let aborted = false;
const session = {
prompt: async () => {},
abort: async () => {
aborted = true;
},
};
await promptWithPrintTimeout(session as any, "say hi", undefined, 5);
assert.equal(aborted, false);
});
test("runPrintMode_when_extension_startup_hangs_still_runs_prompt", async () => {
const logs: string[] = [];
const originalLog = console.log;
console.log = (message?: unknown) => {
logs.push(String(message));
};
try {
const session = {
sessionManager: { getHeader: () => null },
bindExtensions: () => new Promise<void>(() => {}),
subscribe: () => () => undefined,
prompt: async () => {},
abort: async () => {},
state: {
messages: [
{
role: "assistant",
content: [{ type: "text", text: "hi" }],
stopReason: "stop",
},
],
},
};
await runPrintMode(session as any, {
mode: "text",
initialMessage: "say hi",
timeoutMs: 100,
});
assert.deepEqual(logs, ["hi"]);
} finally {
console.log = originalLog;
}
});

View file

@ -6,9 +6,9 @@
* - `pi --mode json "prompt"` - JSON event stream
*/
import { type ChildProcess, spawn } from "node:child_process";
import type { AssistantMessage, ImageContent } from "@singularity-forge/ai";
import type { AgentSession } from "../core/agent-session.js";
import { createDefaultCommandContextActions } from "./shared/command-context-actions.js";
/**
* Options for print mode.
@ -22,6 +22,89 @@ export interface PrintModeOptions {
initialMessage?: string;
/** Images to attach to the initial message */
initialImages?: ImageContent[];
/** Per-prompt timeout in milliseconds. 0 disables the watchdog. */
timeoutMs?: number;
}
const DEFAULT_PRINT_TIMEOUT_MS = 55_000;
export class PrintModeTimeoutError extends Error {
constructor(timeoutMs: number) {
super(
`sf --print timed out after ${timeoutMs}ms waiting for the model response. Set SF_PRINT_TIMEOUT_MS=0 to disable or a larger millisecond value to extend.`,
);
this.name = "PrintModeTimeoutError";
}
}
export function resolvePrintModeTimeoutMs(
env: NodeJS.ProcessEnv = process.env,
): number {
const raw = env.SF_PRINT_TIMEOUT_MS;
if (raw === undefined || raw.trim() === "") return DEFAULT_PRINT_TIMEOUT_MS;
const parsed = Number.parseInt(raw, 10);
if (!Number.isFinite(parsed) || parsed < 0) return DEFAULT_PRINT_TIMEOUT_MS;
return parsed;
}
export async function promptWithPrintTimeout(
session: AgentSession,
message: string,
options: { images?: ImageContent[]; runExtensionHooks?: boolean } | undefined,
timeoutMs: number,
): Promise<void> {
if (timeoutMs <= 0) {
await session.prompt(message, options);
return;
}
const processWatchdog =
timeoutMs >= 1_000 ? startPrintModeProcessWatchdog(timeoutMs) : null;
let timer: ReturnType<typeof setTimeout> | undefined;
const timeout = new PrintModeTimeoutError(timeoutMs);
const timeoutPromise = new Promise<never>((_, reject) => {
timer = setTimeout(() => {
void session.abort().catch(() => {});
reject(timeout);
}, timeoutMs);
});
try {
await Promise.race([session.prompt(message, options), timeoutPromise]);
} finally {
if (timer) clearTimeout(timer);
stopPrintModeProcessWatchdog(processWatchdog);
}
}
function startPrintModeProcessWatchdog(timeoutMs: number): ChildProcess | null {
const script = [
`const timeoutMs = ${JSON.stringify(timeoutMs)};`,
`const pid = ${JSON.stringify(process.pid)};`,
"setTimeout(() => {",
" console.error('sf --print timed out after ' + timeoutMs + 'ms waiting for the model response. Set SF_PRINT_TIMEOUT_MS=0 to disable or a larger millisecond value to extend.');",
" try { process.kill(pid, 'SIGTERM'); } catch {}",
"}, timeoutMs);",
].join("\n");
try {
const child = spawn(process.execPath, ["-e", script], {
stdio: ["ignore", "ignore", "inherit"],
detached: false,
});
child.unref();
return child;
} catch {
return null;
}
}
function stopPrintModeProcessWatchdog(child: ChildProcess | null): void {
if (!child || child.killed) return;
try {
child.kill("SIGTERM");
} catch {
/* already exited */
}
}
/**
@ -33,19 +116,16 @@ export async function runPrintMode(
options: PrintModeOptions,
): Promise<void> {
const { mode, messages = [], initialMessage, initialImages } = options;
const timeoutMs = options.timeoutMs ?? resolvePrintModeTimeoutMs();
if (mode === "json") {
const header = session.sessionManager.getHeader();
if (header) {
console.log(JSON.stringify(header));
}
}
// Set up extensions for print mode (no UI)
await session.bindExtensions({
commandContextActions: createDefaultCommandContextActions(session),
onError: (err) => {
console.error(`Extension error (${err.extensionPath}): ${err.error}`);
},
});
// Print mode intentionally skips extension session_start binding. One-shot
// automation needs bounded prompt output; startup hooks are interactive/RPC
// lifecycle work and have previously blocked `sf -p` before the prompt ran.
// Always subscribe to enable session persistence via _handleAgentEvent
const unsubscribe = session.subscribe((event) => {
@ -83,12 +163,22 @@ export async function runPrintMode(
try {
// Send initial message with attachments
if (initialMessage) {
await session.prompt(initialMessage, { images: initialImages });
await promptWithPrintTimeout(
session,
initialMessage,
{ images: initialImages, runExtensionHooks: false },
timeoutMs,
);
}
// Send remaining messages
for (const message of messages) {
await session.prompt(message);
await promptWithPrintTimeout(
session,
message,
{ runExtensionHooks: false },
timeoutMs,
);
}
// In text mode, output final response
@ -118,7 +208,14 @@ export async function runPrintMode(
}
}
}
} catch (err) {
if (err instanceof PrintModeTimeoutError) {
console.error(err.message);
exitCode = 124;
} else {
throw err;
}
} finally {
// Ensure stdout is fully flushed before returning
// This prevents race conditions where the process exits before all output is written
await new Promise<void>((resolve, reject) => {
@ -127,7 +224,6 @@ export async function runPrintMode(
else resolve();
});
});
} finally {
for (const cleanup of signalCleanupHandlers) cleanup();
disposeSession();
}

View file

@ -661,7 +661,9 @@ const modelRegistry = new ModelRegistry(
settingsManager,
);
markStartup("ModelRegistry");
await warmDiscoveryBackedProviders(modelRegistry);
if (!isPrintMode && cliFlags.listModels === undefined) {
await warmDiscoveryBackedProviders(modelRegistry);
}
markStartup("ModelRegistry.discovery");
// Run onboarding wizard on first launch (no LLM provider configured)

View file

@ -419,7 +419,12 @@ async function defaultAgentRunner(
return await new Promise<AgentRunResult>((resolve) => {
const proc = spawn(launch.command, launch.args, {
cwd: options.cwd ?? process.cwd(),
env: process.env,
env: {
...process.env,
SF_PRINT_TIMEOUT_MS:
process.env.SF_PRINT_TIMEOUT_MS ??
String(Math.max(1_000, DEFAULT_AGENT_TIMEOUT_MS - 5_000)),
},
shell: false,
stdio: ["ignore", "pipe", "pipe"],
});
@ -564,15 +569,13 @@ export async function runTriageApply(
const runContextModule = (await jiti.import(
sfExtensionPath("uok/run-context"),
)) as {
buildUokRunContext: (opts: Record<string, unknown>) =>
| {
surface: string;
runControl: string;
permissionProfile: string;
traceId: string;
parentTrace?: string;
}
| null;
buildUokRunContext: (opts: Record<string, unknown>) => {
surface: string;
runControl: string;
permissionProfile: string;
traceId: string;
parentTrace?: string;
} | null;
};
const traceWriterModule = (await jiti.import(
sfExtensionPath("uok/trace-writer"),
@ -739,10 +742,15 @@ export async function runTriageApply(
// workflows, but --apply uses only the shipped review contract.
if (triageDecider.source !== "builtin" || reviewCode.source !== "builtin") {
const rationale = `non-builtin agents (triage-decider=${triageDecider.source}, review-code=${reviewCode.source})`;
const gateFailure = await emitRequiredTriageGate("trusted-agent-source-gate", "fail", rationale, {
triageDeciderSource: triageDecider.source,
reviewCodeSource: reviewCode.source,
});
const gateFailure = await emitRequiredTriageGate(
"trusted-agent-source-gate",
"fail",
rationale,
{
triageDeciderSource: triageDecider.source,
reviewCodeSource: reviewCode.source,
},
);
if (gateFailure) return gateFailure;
await emit("triage-apply-failed", {
reason: "untrusted-agent-source",
@ -1126,6 +1134,9 @@ export async function handleTriage(
basePath: string,
content: string,
) => string | null;
rankTriageModelsViaRouter: (
candidates?: string[],
) => Promise<string[]>;
};
try {
drainModule = (await jiti.import(
@ -1218,11 +1229,30 @@ export async function handleTriage(
}
if (options.apply) {
// Pre-resolve a model via the router when no --model was supplied and
// no custom runner is injected. Without this, `defaultAgentRunner`
// would spawn `sf -p` with no `--model` flag, and that path hangs
// indefinitely during the subprocess's own model-selection step
// (see sf-mp5tuvdx-ibyk9b). The watchdog still backs this up.
let resolvedModel = options.model;
if (!resolvedModel && !options.agentRunner) {
try {
const ranked = await drainModule.rankTriageModelsViaRouter();
resolvedModel = ranked[0];
} catch (err) {
const msg = err instanceof Error ? err.message : String(err);
process.stderr.write(
`[triage] router pre-resolution failed; falling back to subprocess default: ${msg}\n`,
);
}
}
process.stderr.write(
"[triage] applying via triage-decider -> review-code (this can take a few minutes)…\n",
`[triage] applying via triage-decider -> review-code${
resolvedModel ? ` (model: ${resolvedModel})` : ""
} (this can take a few minutes)\n`,
);
const result = await runTriageApply(cwd, prompt, {
model: options.model,
model: resolvedModel,
agentRunner: options.agentRunner,
candidateCount: candidates.length,
expectedIds: candidates.map((candidate) => candidate.id),

View file

@ -2,10 +2,17 @@ import { randomUUID } from "node:crypto";
import { emitJournalEvent } from "./journal.js";
import { appendTraceEvent } from "./uok/trace-writer.js";
const ROUTE_TRACE_PREFIX = "[sf-route:";
const ROUTE_TRACE_SUFFIX = "]";
const MAX_PENDING_ROUTE_TRACES = 50;
const pendingRouteTraces = [];
const ROUTES = [
{
command: "help",
patterns: [/\b(help|what can i do|commands?)\b/i],
patterns: [
/^(help|show help|open help|what can i do|show commands?|list commands?)$/i,
],
},
{
command: "queue",
@ -79,7 +86,10 @@ const ROUTES = [
},
{
command: "pause",
patterns: [/\b(pause|pause autonomous|take a break)\b/i],
patterns: [
/^(pause|take a break)$/i,
/\bpause\b.*\b(autonomous|sf|run|workflow)\b/i,
],
},
{
command: "stop",
@ -127,7 +137,7 @@ export function routeChatCommand(text) {
function emitChatIntentEvidence(basePath, decision) {
if (!basePath || !decision) return;
const flowId = `chat-intent:${randomUUID()}`;
const flowId = decision.traceId ?? `chat-intent:${randomUUID()}`;
const event = {
input: decision.input,
routedText: decision.routedText,
@ -154,15 +164,46 @@ function emitChatIntentEvidence(basePath, decision) {
});
}
export function extractRouteTracePrefix(text) {
if (!text?.startsWith(ROUTE_TRACE_PREFIX)) {
return { text, routeTraceId: null };
}
const end = text.indexOf(ROUTE_TRACE_SUFFIX);
if (end === -1) return { text, routeTraceId: null };
const routeTraceId = text.slice(ROUTE_TRACE_PREFIX.length, end);
const stripped = text.slice(end + ROUTE_TRACE_SUFFIX.length).trimStart();
return { text: stripped, routeTraceId };
}
export function consumeRouteTraceForCommand(command) {
const index = pendingRouteTraces.findIndex(
(entry) => entry.command === command,
);
if (index === -1) return null;
const [entry] = pendingRouteTraces.splice(index, 1);
return entry;
}
export function registerChatCommandRouter(pi) {
pi.on("input", (event, ctx) => {
if (event.source === "extension") return { action: "continue" };
if (event.images?.length > 0) return { action: "continue" };
const decision = classifyChatCommand(event.text);
if (!decision) return { action: "continue" };
decision.traceId = `chat-intent:${randomUUID()}`;
emitChatIntentEvidence(ctx?.cwd, decision);
pendingRouteTraces.push({
command: decision.command,
traceId: decision.traceId,
input: decision.input,
routedText: decision.routedText,
});
if (pendingRouteTraces.length > MAX_PENDING_ROUTE_TRACES) {
pendingRouteTraces.shift();
}
return {
action: "transform",
text: decision.routedText,
text: `${ROUTE_TRACE_PREFIX}${decision.traceId}${ROUTE_TRACE_SUFFIX} ${decision.routedText}`,
images: event.images,
};
});

View file

@ -1,6 +1,7 @@
import { spawnSync } from "node:child_process";
import { randomUUID } from "node:crypto";
import { importExtensionModule } from "@singularity-forge/coding-agent";
import { consumeRouteTraceForCommand } from "../chat-command-router.js";
import { emitJournalEvent } from "../journal.js";
import { appendTraceEvent } from "../uok/trace-writer.js";
import {
@ -38,7 +39,7 @@ function nextActionForCommand(command, outcome) {
return "continue workflow";
}
function emitCommandEvidence(basePath, traceId, evidence) {
function emitCommandEvidence(basePath, traceId, evidence, parentTrace = null) {
if (!basePath) return;
emitJournalEvent(basePath, {
ts: new Date().toISOString(),
@ -46,10 +47,12 @@ function emitCommandEvidence(basePath, traceId, evidence) {
seq: 1,
eventType: "workflow-command-complete",
rule: "direct-sf-command",
...(parentTrace ? { causedBy: { flowId: parentTrace, seq: 1 } } : {}),
data: evidence,
});
appendTraceEvent(basePath, traceId, {
type: "workflow_command_completion",
...(parentTrace ? { parentTrace } : {}),
surface: "interactive",
runControl:
evidence.command === "autonomous"
@ -73,7 +76,9 @@ async function dispatchDirectSFCommand(command, args, ctx, pi) {
);
const previousStderrSetting = setStderrLoggingEnabled(false);
const basePath = ctx?.cwd ?? process.cwd();
const routedFrom = consumeRouteTraceForCommand(command);
const traceId = `workflow-command:${command}:${randomUUID()}`;
const parentTrace = routedFrom?.traceId ?? null;
const changedBefore = new Set(listChangedFiles(basePath));
const startedAt = Date.now();
let outcome = "pass";
@ -94,16 +99,30 @@ async function dispatchDirectSFCommand(command, args, ctx, pi) {
const newChangedFiles = changedAfter.filter(
(file) => !changedBefore.has(file),
);
emitCommandEvidence(basePath, traceId, {
command,
args: typeof args === "string" ? args.trim() : "",
outcome,
changedFiles: changedAfter,
newChangedFiles,
blockers: blocker ? [blocker] : [],
nextAction: nextActionForCommand(command, outcome),
durationMs: Date.now() - startedAt,
});
emitCommandEvidence(
basePath,
traceId,
{
command,
args: typeof args === "string" ? args.trim() : "",
outcome,
changedFiles: changedAfter,
newChangedFiles,
blockers: blocker ? [blocker] : [],
nextAction: nextActionForCommand(command, outcome),
durationMs: Date.now() - startedAt,
...(routedFrom
? {
routedFrom: {
traceId: routedFrom.traceId,
input: routedFrom.input,
routedText: routedFrom.routedText,
},
}
: {}),
},
parentTrace,
);
}
}

View file

@ -450,7 +450,7 @@ async function readOperatorTriageCandidates() {
*
* Consumer: runTriage (when operator doesn't pass --model).
*/
async function rankTriageModelsViaRouter(candidates) {
export async function rankTriageModelsViaRouter(candidates) {
const candidateList =
(Array.isArray(candidates) && candidates.length > 0
? candidates

View file

@ -6,6 +6,7 @@ import { test } from "vitest";
import guardrails from "../../guardrails/index.js";
import {
classifyChatCommand,
consumeRouteTraceForCommand,
registerChatCommandRouter,
routeChatCommand,
} from "../chat-command-router.js";
@ -85,6 +86,9 @@ test("chat_command_router_maps_clear_chat_intent_to_public_workflow_commands", (
assert.equal(routeChatCommand("I want to see my queue"), "/queue");
assert.equal(routeChatCommand("start autonomous mode"), "/autonomous");
assert.equal(routeChatCommand("let's discuss the architecture"), "/discuss");
assert.equal(routeChatCommand("help me fix login bug"), null);
assert.equal(routeChatCommand("add a pause button"), null);
assert.equal(routeChatCommand("pause autonomous mode"), "/pause");
assert.equal(routeChatCommand("fix the login bug"), null);
assert.equal(routeChatCommand("/queue"), null);
@ -116,16 +120,37 @@ test("chat_command_router_emits_journal_evidence_for_routed_intent", async () =>
const entries = queryJournal(dir, { eventType: "chat-intent-routed" });
assert.equal(result.action, "transform");
assert.equal(result.text, "/queue");
assert.match(result.text, /^\[sf-route:chat-intent:[^\]]+\] \/queue$/);
assert.equal(entries.length, 1);
assert.equal(entries[0].data.command, "queue");
assert.equal(entries[0].data.outcome, "routed");
assert.equal(entries[0].data.nextAction, "execute /queue");
const pending = consumeRouteTraceForCommand("queue");
assert.equal(pending.traceId, entries[0].flowId);
assert.equal(pending.input, "I want to see my queue");
assert.equal(pending.routedText, "/queue");
} finally {
rmSync(dir, { recursive: true, force: true });
}
});
test("chat_command_router_does_not_route_extension_generated_input", async () => {
let inputHandler;
registerChatCommandRouter({
on(event, handler) {
if (event === "input") inputHandler = handler;
},
});
const result = await inputHandler(
{ text: "I want to see my queue", images: undefined, source: "extension" },
{ cwd: process.cwd() },
);
assert.deepEqual(result, { action: "continue" });
});
test("direct command completions strip the already typed command name", () => {
assert.deepEqual(getSfTopLevelCommandCompletions("autonomous", "--"), [
{