From f2137becb80b2817eb8a8e062f6d1d88ad474a98 Mon Sep 17 00:00:00 2001 From: can1357 Date: Wed, 10 Jun 2026 02:17:34 +0200 Subject: [PATCH] fix: fixed prompt parsing, startup tracing, and help-command behavior - Fixed help rendering so `--help` no longer triggers unrelated command loaders. - Fixed startup span logging to emit markers only with PI_DEBUG_STARTUP set. - Fixed logger startup trace behavior for `:start`, `:done`, and `:fail` phases. - Fixed prompt template processing with cached raw-template compilation and safer formatting. - Optimized symbol and tag parsing in prompt templates via manual parsers. --- docs/environment-variables.md | 1 + packages/coding-agent/CHANGELOG.md | 7 + packages/coding-agent/src/capability/fs.ts | 10 + .../coding-agent/src/config/model-registry.ts | 18 +- packages/coding-agent/src/main.ts | 78 +++++- .../src/prompts/agents/explore.md | 2 +- packages/coding-agent/src/sdk.ts | 11 +- .../src/session/auth-broker-config.ts | 31 ++- .../src/ssh/connection-manager.ts | 27 +++ packages/coding-agent/src/task/index.ts | 35 ++- .../test/capability/fs-special-files.test.ts | 52 ++++ .../test/sdk-mcp-discovery.test.ts | 2 +- .../test/task/create-memo.test.ts | 66 +++++ .../test/tools/ssh-description.test.ts | 54 +++++ packages/natives/CHANGELOG.md | 1 + packages/natives/native/loader-state.js | 19 ++ packages/utils/CHANGELOG.md | 9 + packages/utils/src/cli.ts | 41 +++- packages/utils/src/logger.ts | 182 ++++++++++---- packages/utils/src/prompt.ts | 225 ++++++++++++------ packages/utils/test/cli-help.test.ts | 42 ++++ packages/utils/test/logger-startup.test.ts | 95 ++++++++ packages/utils/test/prompt.test.ts | 96 ++++++++ 23 files changed, 966 insertions(+), 138 deletions(-) create mode 100644 packages/coding-agent/test/capability/fs-special-files.test.ts create mode 100644 packages/coding-agent/test/task/create-memo.test.ts create mode 100644 packages/coding-agent/test/tools/ssh-description.test.ts create mode 100644 packages/utils/test/cli-help.test.ts create mode 100644 packages/utils/test/logger-startup.test.ts create mode 100644 packages/utils/test/prompt.test.ts diff --git a/docs/environment-variables.md b/docs/environment-variables.md index b5f5c59be..0466d800f 100644 --- a/docs/environment-variables.md +++ b/docs/environment-variables.md @@ -314,6 +314,7 @@ Extra conditional behavior: | `PI_TASK_MAX_OUTPUT_BYTES` | Max captured output bytes per subagent (default `500000`) | | `PI_TASK_MAX_OUTPUT_LINES` | Max captured output lines per subagent (default `5000`) | | `PI_TIMING` | If set (any non-empty value), prints a hierarchical timing-span tree to **stderr** via `logger.printTimings()`. In interactive mode the tree prints once the agent is ready (before the TUI starts); in print mode it prints after the whole prompt batch completes. Print-mode prompts are wrapped in `print:prompt:initial` / `print:prompt:next` spans so each user message shows up as its own row. `PI_TIMING=x` exits the process with code 0 right after printing in interactive mode (use to measure cold startup only). `PI_TIMING=full` lists every module-load entry instead of just the top N. | +| `PI_DEBUG_STARTUP` | If set (any non-empty value), streams one synchronous `[startup] :start` / `:done` marker line to **stderr** as each startup phase begins/ends — including command-module imports (`cli:load:`) and the native addon extraction/`dlopen` (`native:*`). Unlike `PI_TIMING` (which prints only once startup completes), the markers survive a hard hang: the last line on stderr names the phase the process is stuck in. Combine with `PI_TIMING` freely; markers and the span tree share the same phase names. | | `PI_PACKAGE_DIR` | Overrides package asset base dir resolution (`docs/`, `examples/`, `CHANGELOG.md`) | | `PI_DISABLE_LSPMUX` | If `1`, disables lspmux detection/integration and forces direct LSP server spawning | | `PI_RPC_EMIT_TITLE` | Boolean-like flag enabling title events in RPC mode | diff --git a/packages/coding-agent/CHANGELOG.md b/packages/coding-agent/CHANGELOG.md index 8bbe5abd8..dc3deca88 100644 --- a/packages/coding-agent/CHANGELOG.md +++ b/packages/coding-agent/CHANGELOG.md @@ -1,12 +1,17 @@ # Changelog ## [Unreleased] + ### Added - New `omp usage` command: a detailed per-account breakdown of provider usage limits (bars, windows, reset times, plan metadata) covering every stored credential — accounts with no usage endpoint are listed as "no usage data" rows. Each provider section ends with per-window capacity stats ("need: 5h → 3 of 5 accounts"). Flags: `--provider` to filter, `--json` for the broker-shaped report payload, and `--redact` to mask account emails/ids down to a two-char anchor plus a minimal middle-out differentiator (`ca*9*`) for screenshot-safe sharing. +- Startup hangs are now self-diagnosing (speculative fix for the "zero output, hangs even on `omp -h`" report class): a watchdog prints a stderr line every 10s naming the deepest in-flight startup phase (via `logger.openSpanPath()`) until a mode runner takes over, pausing around legitimate interactive waits (fork/move prompts, the `--resume` session picker); `PI_DEBUG_STARTUP` is restored as streaming synchronous `[startup]` phase markers covering command-module imports and the native addon load, which the post-startup `PI_TIMING` tree structurally cannot show for a hang; and waiting on piped-stdin EOF announces itself after 1s instead of blocking silently. ### Changed +- Cached custom model alias maps and built them lazily on first custom model reference lookup, avoiding unnecessary startup model-registry initialization +- Cached resolved auth broker configuration and snapshot reads for the process lifetime so repeated startup paths reuse the same `OMP_AUTH_BROKER_*` resolution instead of re-running config/token discovery +- Reused task-agent discovery results for repeated `TaskTool.create` calls in the same working directory to avoid repeated plugin scans during subagent startup - Tightened the system prompt and tool prompts: deduped restated warnings (bash "catch yourself" list, search/find shell-fallback recaps, read instruction/critical overlap, the AST metavariable primer duplicated across both ast tool descriptions), factored the repeated repo-default clause in the `gh` search ops, dropped a dead `rsed` reference and an internal `tool-timeouts.ts` pointer, and pruned internal mechanism the agent can't act on (screenshot temp-file/downscaling pipeline, browser spawn lifecycle, `gh` "replaces former op" history and run-watch grace period, output-minimizer heuristics, BM25 ranking name, `task.maxConcurrency` pointer) - Extended the prompt-efficiency pass to the full prompt surface (subagent/plan-mode/notice/title/commit system prompts, agent definitions, goals, memories, review and autoresearch prompts): RFC-keyed prescriptive prose, fixed garbled grammar and a stale `` placeholder in the plan-approval reminder, deduped intra-file restatements, and corrected the `todo` op table's claim that `rm` requires a `task`/`phase` (bare `rm` clears the whole list) - Replace tool prompt no longer recommends `sed -i`/`cat`-heredoc commands that the bash interceptor blocks; its bash-alternatives table now only lists non-intercepted commands @@ -24,6 +29,8 @@ ### Fixed +- Fixed the bundled `explore` agent's `thinking-level: med` frontmatter — not a valid effort (`minimal`/`low`/`medium`/`high`/`xhigh`), so it silently parsed to undefined and the agent ran without its intended thinking level +- Discovery context-file reads (`~/.claude`, `~/.cursor`, project trees, `@`-imports) now stat-gate to regular files before reading: a FIFO/socket/char device dropped where a context file is expected previously blocked startup forever on a read that can never see EOF. - Kept IRC cards from being removed after their TTL once everything above them finalized: their rows may already be committed to native scrollback, and removing them was an interior deletion of the committed prefix that the engine could only repair by recommitting everything below the gap (duplicated blocks). Such cards now stay in the transcript as durable history. - Fixed the recommit storm that sprayed stale snapshots of a running task's progress tree into native scrollback. The stable-prefix ratchet promoted any row quiet for one 30-frame window, so slowly ticking rows (per-agent tool/cost counters updating every few seconds) were repeatedly promoted, committed, rewritten, and recommitted by the engine audit for the whole run. The ratchet now floors itself permanently at the first row that mutates after being promoted — settled heads (a task's prompt/context) still reach scrollback, genuine tickers never re-promote. - **Fixed the artifact spill dropping the first ~20KB of output**: head-retained bytes were never written to the artifact file, so for every bash/eval/ssh command exceeding the 50KB spill threshold, the `artifact://` advertised as the "full capture" was permanently missing its head — the agent re-reading it got truncated data presented as lossless. diff --git a/packages/coding-agent/src/capability/fs.ts b/packages/coding-agent/src/capability/fs.ts index 94764592b..fd9a5d226 100644 --- a/packages/coding-agent/src/capability/fs.ts +++ b/packages/coding-agent/src/capability/fs.ts @@ -15,6 +15,16 @@ export async function readFile(filePath: string): Promise { } try { + // Gate on the file type first: discovery scans foreign config dirs + // (~/.claude, ~/.cursor, project trees), and reading a FIFO/socket/char + // device with `.text()` blocks until EOF — i.e. forever — hanging + // startup with zero output. `stat` follows symlinks, so symlinked + // context files (CLAUDE.md -> AGENTS.md) still resolve. + const stats = await fs.promises.stat(abs); + if (!stats.isFile()) { + contentCache.set(abs, null); + return null; + } const content = await Bun.file(abs).text(); contentCache.set(abs, content); return content; diff --git a/packages/coding-agent/src/config/model-registry.ts b/packages/coding-agent/src/config/model-registry.ts index a1cfcb200..284aad050 100644 --- a/packages/coding-agent/src/config/model-registry.ts +++ b/packages/coding-agent/src/config/model-registry.ts @@ -774,8 +774,19 @@ function buildCustomReferenceSuffixAliasMap(exactReferences: ReadonlyMap> | undefined; +let customReferenceSuffixAliasMap: Map> | undefined; + +function getCustomReferenceMaps(): { exact: Map>; suffixAlias: Map> } { + if (customReferenceMap === undefined || customReferenceSuffixAliasMap === undefined) { + customReferenceMap = buildCustomReferenceMap(); + customReferenceSuffixAliasMap = buildCustomReferenceSuffixAliasMap(customReferenceMap); + } + return { exact: customReferenceMap, suffixAlias: customReferenceSuffixAliasMap }; +} const CUSTOM_REFERENCE_TRAILING_MARKER_PATTERN = /[-:](?:thinking|customtools|high|low|medium|minimal|xhigh|free|cloud|exacto|nitro|original|optimized|nvfp4|fp8|fp4|bf16|int8|int4|search)$/i; @@ -830,9 +841,10 @@ function getCustomReferenceCandidateIds(modelId: string): string[] { } function resolveCustomModelReference(modelId: string): Model | undefined { + const { exact, suffixAlias } = getCustomReferenceMaps(); for (const candidate of getCustomReferenceCandidateIds(modelId)) { const key = normalizeCustomReferenceKey(candidate); - const reference = customReferenceMap.get(key) ?? customReferenceSuffixAliasMap.get(key); + const reference = exact.get(key) ?? suffixAlias.get(key); if (reference) return reference; } return undefined; diff --git a/packages/coding-agent/src/main.ts b/packages/coding-agent/src/main.ts index b690978d0..91dd2dc07 100644 --- a/packages/coding-agent/src/main.ts +++ b/packages/coding-agent/src/main.ts @@ -11,6 +11,7 @@ import { EventLoopKeepalive } from "@oh-my-pi/pi-agent-core"; import type { ImageContent } from "@oh-my-pi/pi-ai"; import { $env, + getLogPath, getProjectDir, logger, normalizePathForComparison, @@ -143,15 +144,79 @@ function applyAcpDefaultSettingOverrides(targetSettings: Settings = settings): v async function readPipedInput(): Promise { if (process.stdin.isTTY !== false) return undefined; + // stdin is a pipe: a producer that never writes nor closes would block + // startup forever with zero output. Say what we're blocked on after 1s. + const notice = setTimeout(() => { + process.stderr.write(`${chalk.dim("Reading prompt from piped stdin (waiting for EOF; ctrl+c to abort)…")}\n`); + }, 1000); + notice.unref?.(); try { const text = await Bun.stdin.text(); if (text.trim().length === 0) return undefined; return text; } catch { return undefined; + } finally { + clearTimeout(notice); } } +// --------------------------------------------------------------------------- +// Startup watchdog +// --------------------------------------------------------------------------- +// Speculative-hang reporter: until startup hands off to a mode runner, print a +// stderr line every 10s naming the deepest in-flight startup phase. Turns +// zero-output indefinite hangs (stuck discovery read, network wait, stdin +// pipe) into self-diagnosing reports instead of "it just hangs" (see the +// PI_DEBUG_STARTUP markers for the synchronous-hang counterpart). + +const STARTUP_WATCHDOG_INTERVAL_MS = 10_000; +let startupWatchdogTimer: NodeJS.Timeout | undefined; +let startupWatchdogActive = false; +let startupWatchdogStartedAt = 0; + +function armStartupWatchdog(): void { + if (startupWatchdogTimer) return; + startupWatchdogTimer = setInterval(() => { + const elapsed = Math.round((Date.now() - startupWatchdogStartedAt) / 1000); + const phase = logger.openSpanPath().join(" > ") || "module load / pre-phase work"; + process.stderr.write( + `${chalk.yellow(`Still starting after ${elapsed}s`)}${chalk.dim(` — phase: ${phase}`)}\n` + + `${chalk.dim(` logs: ${getLogPath()} · re-run with PI_DEBUG_STARTUP=1 for streaming phase markers`)}\n`, + ); + }, STARTUP_WATCHDOG_INTERVAL_MS); + startupWatchdogTimer.unref?.(); +} + +function disarmStartupWatchdog(): void { + if (!startupWatchdogTimer) return; + clearInterval(startupWatchdogTimer); + startupWatchdogTimer = undefined; +} + +/** Begin watching startup (idempotent). */ +function startStartupWatchdog(): void { + startupWatchdogActive = true; + startupWatchdogStartedAt = Date.now(); + armStartupWatchdog(); +} + +/** Permanently stop watching: a mode runner now owns the terminal. */ +function stopStartupWatchdog(): void { + startupWatchdogActive = false; + disarmStartupWatchdog(); +} + +/** Pause while an interactive prompt legitimately waits on the user. */ +function pauseStartupWatchdog(): void { + disarmStartupWatchdog(); +} + +/** Resume after an interactive prompt, if startup is still being watched. */ +function resumeStartupWatchdog(): void { + if (startupWatchdogActive) armStartupWatchdog(); +} + export interface InteractiveModeNotify { kind: "warn" | "error" | "info"; message: string; @@ -361,12 +426,14 @@ async function promptForkSession(session: SessionInfo): Promise { logger.startTiming(); + startStartupWatchdog(); // Initialize theme early with defaults (CLI commands need symbols) // Will be re-initialized with user preferences later @@ -803,7 +873,7 @@ export async function runRootCommand( const notifs: (InteractiveModeNotify | null)[] = []; // Create AuthStorage and ModelRegistry upfront - const authStorage = await logger.time("discoverModels", deps.discoverAuthStorage ?? discoverAuthStorage); + const authStorage = await logger.time("discoverAuthStorage", deps.discoverAuthStorage ?? discoverAuthStorage); const modelRegistry = new ModelRegistry(authStorage); if (parsedArgs.version) { @@ -991,10 +1061,12 @@ export async function runRootCommand( } startInAllScope = true; } + pauseStartupWatchdog(); const selected = await logger.time("selectSession", selectSession, folderSessions, { allSessions: preloadedAllSessions, startInAllScope, }); + resumeStartupWatchdog(); if (!selected) { process.stdout.write(`${chalk.dim("No session selected")}\n`); return; @@ -1086,6 +1158,7 @@ export async function runRootCommand( }); // Branch-only protocol runner: keep ACP server code out of normal interactive startup. const runAcpMode = deps.runAcpMode ?? (await import("./modes/acp/acp-mode")).runAcpMode; + stopStartupWatchdog(); await runAcpMode(createAcpSession); } else { // Resolve extension-registered CLI flags before creating the session so a @@ -1152,6 +1225,7 @@ export async function runRootCommand( if (mode === "rpc" || mode === "rpc-ui") { // Branch-only protocol runner: keep RPC host code out of normal interactive startup. const runRpcMode: RunRpcMode = (await import("./modes/rpc/rpc-mode")).runRpcMode; + stopStartupWatchdog(); await runRpcMode(session, mode === "rpc-ui" ? setToolUIContext : undefined); } else if (isInteractive) { const versionCheckPromise = checkForNewVersion(VERSION).catch(() => undefined); @@ -1175,6 +1249,7 @@ export async function runRootCommand( } } + stopStartupWatchdog(); logger.endTiming(); await runInteractiveMode( session, @@ -1194,6 +1269,7 @@ export async function runRootCommand( ); } else { // Branch-only single-shot runner: keep print-mode code out of normal interactive startup. + stopStartupWatchdog(); const runPrintMode: RunPrintMode = (await import("./modes/print-mode")).runPrintMode; await runPrintMode(session, { mode, diff --git a/packages/coding-agent/src/prompts/agents/explore.md b/packages/coding-agent/src/prompts/agents/explore.md index a193eaf90..f9a85c601 100644 --- a/packages/coding-agent/src/prompts/agents/explore.md +++ b/packages/coding-agent/src/prompts/agents/explore.md @@ -3,7 +3,7 @@ name: explore description: Fast read-only codebase scout returning compressed context for handoff tools: read, search, find, web_search model: pi/smol -thinking-level: med +thinking-level: medium read-summarize: false output: properties: diff --git a/packages/coding-agent/src/sdk.ts b/packages/coding-agent/src/sdk.ts index 730c0bca1..c435949b3 100644 --- a/packages/coding-agent/src/sdk.ts +++ b/packages/coding-agent/src/sdk.ts @@ -531,11 +531,18 @@ function resolveSnapshotTtlMs(): number { * override to re-mint access tokens when needed. */ export async function discoverAuthStorage(agentDir: string = getDefaultAgentDir()): Promise { - const brokerConfig = await resolveAuthBrokerConfig(); + const brokerConfigPromise = resolveAuthBrokerConfig(); + const cachePath = getAuthBrokerSnapshotCachePath(); + // Warm the encrypted snapshot cache into the page cache while the broker + // config resolves (it may shell out for a `!command` token). Decryption + // needs the resolved token, so the real cache read cannot start earlier. + void Bun.file(cachePath) + .arrayBuffer() + .catch(() => undefined); + const brokerConfig = await brokerConfigPromise; if (brokerConfig) { const client = new AuthBrokerClient({ url: brokerConfig.url, token: brokerConfig.token }); const ttlMs = resolveSnapshotTtlMs(); - const cachePath = getAuthBrokerSnapshotCachePath(); const persist = ttlMs > 0 ? (snapshot: SnapshotResponse): void => { diff --git a/packages/coding-agent/src/session/auth-broker-config.ts b/packages/coding-agent/src/session/auth-broker-config.ts index 33d543050..2c015b4cd 100644 --- a/packages/coding-agent/src/session/auth-broker-config.ts +++ b/packages/coding-agent/src/session/auth-broker-config.ts @@ -65,13 +65,42 @@ async function readConfigYaml(): Promise { } } +/** + * Process-lifetime memo for {@link resolveAuthBrokerConfig}. Keyed on the env + * inputs (plus agent dir, which decides which config.yml is read) so tests + * that flip `OMP_AUTH_BROKER_*` between cases still observe the change, while + * repeated resolution within one CLI invocation (startup, subagent sessions) + * skips the config.yml read and any `!command` token resolution. + */ +let cachedConfigKey: string | null = null; +let cachedConfigPromise: Promise | null = null; + /** * Read broker configuration. Returns null when the URL is missing * (broker disabled — local store is used). Throws when URL is set but no * token is available — the caller cannot fall back silently because the * user explicitly asked to use the broker. + * + * Successful resolutions (including "no broker configured") are memoized for + * the process lifetime; failures are not, so a missing token can be fixed and + * retried. Concurrent callers share one in-flight resolution. */ -export async function resolveAuthBrokerConfig(): Promise { +export function resolveAuthBrokerConfig(): Promise { + const key = `${process.env.OMP_AUTH_BROKER_URL ?? ""}\u0000${process.env.OMP_AUTH_BROKER_TOKEN ?? ""}\u0000${getAgentDir()}`; + if (cachedConfigPromise && cachedConfigKey === key) return cachedConfigPromise; + const promise = resolveAuthBrokerConfigUncached(); + cachedConfigKey = key; + cachedConfigPromise = promise; + promise.catch(() => { + if (cachedConfigPromise === promise) { + cachedConfigPromise = null; + cachedConfigKey = null; + } + }); + return promise; +} + +async function resolveAuthBrokerConfigUncached(): Promise { const envUrl = process.env.OMP_AUTH_BROKER_URL; const envToken = process.env.OMP_AUTH_BROKER_TOKEN; diff --git a/packages/coding-agent/src/ssh/connection-manager.ts b/packages/coding-agent/src/ssh/connection-manager.ts index 23598b75c..b415f6ba5 100644 --- a/packages/coding-agent/src/ssh/connection-manager.ts +++ b/packages/coding-agent/src/ssh/connection-manager.ts @@ -355,6 +355,33 @@ export async function getHostInfoForHost(host: SSHConnectionTarget): Promise { const cached = hostInfoCache.get(host.name); if (cached) { diff --git a/packages/coding-agent/src/task/index.ts b/packages/coding-agent/src/task/index.ts index a88b8fe49..2bc59a45b 100644 --- a/packages/coding-agent/src/task/index.ts +++ b/packages/coding-agent/src/task/index.ts @@ -43,7 +43,7 @@ import type { LocalProtocolOptions } from "../internal-urls"; import { loadOverallPlanReference } from "../plan-mode/plan-handoff"; import { generateCommitMessage } from "../utils/commit-message-generator"; import * as git from "../utils/git"; -import { discoverAgents, getAgent } from "./discovery"; +import { type DiscoveryResult, discoverAgents, getAgent } from "./discovery"; import { runSubprocess } from "./executor"; import { AgentOutputManager } from "./output-manager"; import { mapWithConcurrencyLimit, Semaphore } from "./parallel"; @@ -293,6 +293,37 @@ function validateTaskIds(tasks: TaskParams["tasks"]): string | undefined { return `Invalid tasks: ${problems.join(". ")}`; } +/** + * Process-level memo for create-time agent discovery, keyed by resolved cwd. + * + * `TaskTool.create` runs for every (sub)agent session in this process and the + * walk-up + plugin-registry scan in `discoverAgents` is identical for a given + * cwd, so repeat creations reuse the first scan. Execution-time discovery + * (`#executeSync`) intentionally stays fresh. The memo also tracks the live + * `discoverAgents` binding: test spies swap that binding, which invalidates + * the memo automatically. + */ +const discoveryMemo = new Map>(); +let discoveryMemoFn: typeof discoverAgents | undefined; + +function discoverAgentsForCreate(cwd: string): Promise { + const fn = discoverAgents; + if (discoveryMemoFn !== fn) { + discoveryMemoFn = fn; + discoveryMemo.clear(); + } + const key = path.resolve(cwd); + let pending = discoveryMemo.get(key); + if (!pending) { + pending = fn(cwd); + discoveryMemo.set(key, pending); + pending.catch(() => { + if (discoveryMemo.get(key) === pending) discoveryMemo.delete(key); + }); + } + return pending; +} + // ═══════════════════════════════════════════════════════════════════════════ // Tool Class // ═══════════════════════════════════════════════════════════════════════════ @@ -376,7 +407,7 @@ export class TaskTool implements AgentTool { - const { agents } = await discoverAgents(session.cwd); + const { agents } = await discoverAgentsForCreate(session.cwd); return new TaskTool(session, agents); } diff --git a/packages/coding-agent/test/capability/fs-special-files.test.ts b/packages/coding-agent/test/capability/fs-special-files.test.ts new file mode 100644 index 000000000..d766d524b --- /dev/null +++ b/packages/coding-agent/test/capability/fs-special-files.test.ts @@ -0,0 +1,52 @@ +import { afterAll, beforeAll, describe, expect, it } from "bun:test"; +import * as fs from "node:fs"; +import * as os from "node:os"; +import * as path from "node:path"; +import { clearCache, readFile } from "@oh-my-pi/pi-coding-agent/capability/fs"; + +const isWindows = process.platform === "win32"; + +describe("capability/fs readFile on special files", () => { + let dir = ""; + + beforeAll(async () => { + dir = await fs.promises.mkdtemp(path.join(os.tmpdir(), "omp-fs-special-")); + }); + + afterAll(async () => { + await fs.promises.rm(dir, { recursive: true, force: true }); + }); + + // Contract: discovery scans foreign config dirs (~/.claude, ~/.cursor, + // project trees). A FIFO/socket dropped where a context file is expected + // must yield null instead of blocking startup forever on a read that can + // never see EOF. + it.skipIf(isWindows)("returns null for a FIFO instead of blocking", async () => { + const fifo = path.join(dir, "CLAUDE.md"); + const made = Bun.spawnSync(["mkfifo", fifo]); + expect(made.exitCode).toBe(0); + clearCache(); + // Real-clock race on purpose: a regressed readFile blocks inside a + // kernel read() on the FIFO — there is no promise or event to await and + // fake timers cannot advance a syscall. The sleep only bounds the + // failure; the passing path returns immediately. + const result = await Promise.race([readFile(fifo), Bun.sleep(1500).then(() => "HUNG" as const)]); + if (result === "HUNG") { + // Regression path: unblock the leaked FIFO reader so the test + // process can exit, then fail on the assertion below. + fs.closeSync(fs.openSync(fifo, "w")); + } + expect(result).toBeNull(); + }); + + // Symlinked context files (CLAUDE.md -> AGENTS.md) are common; the type + // gate must follow links rather than rejecting them. + it.skipIf(isWindows)("still reads regular files through symlinks", async () => { + const target = path.join(dir, "AGENTS.md"); + await Bun.write(target, "# context"); + const link = path.join(dir, "CLAUDE-link.md"); + await fs.promises.symlink(target, link); + clearCache(); + expect(await readFile(link)).toBe("# context"); + }); +}); diff --git a/packages/coding-agent/test/sdk-mcp-discovery.test.ts b/packages/coding-agent/test/sdk-mcp-discovery.test.ts index 68b02fa05..b7f35eecd 100644 --- a/packages/coding-agent/test/sdk-mcp-discovery.test.ts +++ b/packages/coding-agent/test/sdk-mcp-discovery.test.ts @@ -247,7 +247,7 @@ describe("createAgentSession MCP discovery prompt gating", () => { const searchTool = session.agent.state.tools.find(tool => tool.name === "search_tool_bm25"); expect(searchTool?.description).toContain("Total discoverable tools available: 1."); - expect(searchTool?.description).toContain("- `server_name`"); + expect(searchTool?.description).toContain("Discoverable MCP servers in this session: github (1 tool)."); }); it("prunes deactivated builtin discoveries so they can be rediscovered", async () => { diff --git a/packages/coding-agent/test/task/create-memo.test.ts b/packages/coding-agent/test/task/create-memo.test.ts new file mode 100644 index 000000000..ee63123fc --- /dev/null +++ b/packages/coding-agent/test/task/create-memo.test.ts @@ -0,0 +1,66 @@ +import { afterEach, describe, expect, it, vi } from "bun:test"; +import { Settings } from "@oh-my-pi/pi-coding-agent/config/settings"; +import { TaskTool } from "@oh-my-pi/pi-coding-agent/task"; +import * as discoveryModule from "@oh-my-pi/pi-coding-agent/task/discovery"; +import type { ToolSession } from "@oh-my-pi/pi-coding-agent/tools"; + +const TEST_AGENTS = [ + { + name: "task", + description: "General-purpose task agent", + systemPrompt: "You are a task agent.", + source: "bundled" as const, + }, +]; + +function createSession(cwd: string): ToolSession { + return { + cwd, + hasUI: false, + settings: Settings.isolated({}), + getSessionFile: () => null, + getSessionSpawns: () => "*", + } as unknown as ToolSession; +} + +describe("TaskTool.create discovery memo", () => { + afterEach(() => { + vi.restoreAllMocks(); + }); + + it("reuses one discovery scan across repeated creations with the same cwd", async () => { + const spy = vi + .spyOn(discoveryModule, "discoverAgents") + .mockResolvedValue({ agents: TEST_AGENTS, projectAgentsDir: null }); + + const first = await TaskTool.create(createSession("/tmp")); + const second = await TaskTool.create(createSession("/tmp")); + + expect(spy).toHaveBeenCalledTimes(1); + expect(first.description).toBe(second.description); + }); + + it("rescans for a different cwd", async () => { + const spy = vi + .spyOn(discoveryModule, "discoverAgents") + .mockResolvedValue({ agents: TEST_AGENTS, projectAgentsDir: null }); + + await TaskTool.create(createSession("/tmp")); + await TaskTool.create(createSession("/tmp/omp-memo-other")); + + expect(spy).toHaveBeenCalledTimes(2); + }); + + it("does not cache a rejected discovery", async () => { + const spy = vi + .spyOn(discoveryModule, "discoverAgents") + .mockRejectedValueOnce(new Error("boom")) + .mockResolvedValue({ agents: TEST_AGENTS, projectAgentsDir: null }); + + await expect(TaskTool.create(createSession("/tmp"))).rejects.toThrow("boom"); + const tool = await TaskTool.create(createSession("/tmp")); + + expect(tool.description).toContain("task"); + expect(spy).toHaveBeenCalledTimes(2); + }); +}); diff --git a/packages/coding-agent/test/tools/ssh-description.test.ts b/packages/coding-agent/test/tools/ssh-description.test.ts new file mode 100644 index 000000000..673ea3180 --- /dev/null +++ b/packages/coding-agent/test/tools/ssh-description.test.ts @@ -0,0 +1,54 @@ +import { afterEach, describe, expect, it, vi } from "bun:test"; +import type { SSHHost } from "@oh-my-pi/pi-coding-agent/capability/ssh"; +import type { SourceMeta } from "@oh-my-pi/pi-coding-agent/capability/types"; +import * as discovery from "@oh-my-pi/pi-coding-agent/discovery"; +import type { ToolSession } from "@oh-my-pi/pi-coding-agent/tools"; +import { loadSshTool } from "@oh-my-pi/pi-coding-agent/tools"; + +const SOURCE: SourceMeta = { + provider: "test", + providerName: "Test", + path: "/dev/null", + level: "user", +}; + +// Unique names so no persisted host-info cache file can exist for them. +const RUN_ID = `${Date.now()}-${process.pid}`; +const HOST_A: SSHHost = { name: `a-omp-test-${RUN_ID}`, host: "alpha.example.com", _source: SOURCE }; +const HOST_B: SSHHost = { name: `b-omp-test-${RUN_ID}`, host: "beta.example.com", _source: SOURCE }; + +function mockHosts(hosts: SSHHost[]): void { + vi.spyOn(discovery, "loadCapability").mockResolvedValue({ + items: hosts, + all: hosts, + warnings: [], + providers: ["test"], + }); +} + +function createSession(): ToolSession { + return { cwd: "/tmp" } as unknown as ToolSession; +} + +describe("loadSshTool description", () => { + afterEach(() => { + vi.restoreAllMocks(); + }); + + it("returns null when no hosts are configured", async () => { + mockHosts([]); + expect(await loadSshTool(createSession())).toBeNull(); + }); + + it("renders uncached hosts with the detecting placeholder, sorted by name, without probing", async () => { + mockHosts([HOST_B, HOST_A]); + const tool = await loadSshTool(createSession()); + expect(tool).not.toBeNull(); + expect(tool?.description.startsWith("Runs commands on remote hosts.")).toBe(true); + expect( + tool?.description.endsWith( + `\n\nAvailable hosts:\n- ${HOST_A.name} (${HOST_A.host}) | detecting...\n- ${HOST_B.name} (${HOST_B.host}) | detecting...`, + ), + ).toBe(true); + }); +}); diff --git a/packages/natives/CHANGELOG.md b/packages/natives/CHANGELOG.md index e21820228..3ad9d8dd8 100644 --- a/packages/natives/CHANGELOG.md +++ b/packages/natives/CHANGELOG.md @@ -5,6 +5,7 @@ ### Added - Added a `maxCountPerFile` option to `grep` that caps how many matches a single file may contribute, so one hot file can no longer exhaust the global `maxCount` budget in path order and starve every file sorted after it out of the result set entirely. +- Added `PI_DEBUG_STARTUP` streaming markers to the addon loader (`native:loadNative:start`, `native:extractEmbeddedAddon:start`, `native:require:`, `native:loadNative:done`), written with synchronous stderr writes so a hang inside first-run extraction or `dlopen()` — which blocks the event loop and defeats any timer-based diagnostics — still leaves the failing step as the last marker on stderr. - Added a `skippedOversized` count to `GrepResult`: directory walks now report how many files were silently skipped for exceeding the 4MB per-file grep limit (previously they vanished without a trace, letting callers conclude a symbol does not exist). ### Changed diff --git a/packages/natives/native/loader-state.js b/packages/natives/native/loader-state.js index 13d43fed9..179ff5293 100644 --- a/packages/natives/native/loader-state.js +++ b/packages/natives/native/loader-state.js @@ -33,6 +33,21 @@ import { embeddedAddon } from "./embedded-addon.js"; const SUPPORTED_PLATFORMS = ["linux-x64", "linux-arm64", "darwin-x64", "darwin-arm64", "win32-x64"]; +/** + * Streaming startup marker, enabled by `PI_DEBUG_STARTUP`. Local copy of the + * pi-utils helper (this loader cannot depend on pi-utils). Synchronous on + * purpose: extraction/dlopen hangs must still leave the `:start` marker. + * @param {string} text + */ +function startupMarker(text) { + if (!process.env.PI_DEBUG_STARTUP) return; + try { + fs.writeSync(2, `[startup] ${text}\n`); + } catch { + // stderr unavailable; markers are best-effort + } +} + function getNativesDir() { const xdgDataHome = process.env.XDG_DATA_HOME; if (xdgDataHome && fs.existsSync(path.join(xdgDataHome, "omp"))) { @@ -366,6 +381,7 @@ function maybeExtractEmbeddedAddon(ctx, errors) { if (!selectedEmbeddedFile) return null; const targetPath = path.join(ctx.versionedDir, selectedEmbeddedFile.filename); + startupMarker("native:extractEmbeddedAddon:start"); try { fs.mkdirSync(ctx.versionedDir, { recursive: true }); } catch (err) { @@ -564,6 +580,7 @@ function initLoaderContext() { } export function loadNative() { + startupMarker("native:loadNative:start"); const ctx = initLoaderContext(); const require_ = createRequire(import.meta.url); @@ -575,8 +592,10 @@ export function loadNative() { for (const candidate of runtimeCandidates) { try { + startupMarker(`native:require:${path.basename(candidate)}`); const bindings = require_(candidate); validateLoadedBindings(ctx, bindings, candidate); + startupMarker("native:loadNative:done"); return bindings; } catch (err) { const message = err instanceof Error ? err.message : String(err); diff --git a/packages/utils/CHANGELOG.md b/packages/utils/CHANGELOG.md index b721fac85..9b4c3f511 100644 --- a/packages/utils/CHANGELOG.md +++ b/packages/utils/CHANGELOG.md @@ -1,11 +1,20 @@ # Changelog ## [Unreleased] +### Added + +- Restored `PI_DEBUG_STARTUP` streaming startup markers: `logger.time` now writes a synchronous `[startup] :start` / `:done` / `:fail` stderr line per phase (independent of `PI_TIMING`), so a startup that hangs hard still names the phase it is stuck in — the `PI_TIMING` tree only prints after startup completes and is structurally unable to diagnose a hang. The CLI runner emits `cli:load:` markers around each lazily-imported command module for the same reason. +- Added `logger.openSpanPath()`: ops of the currently-open timing-span chain (root → deepest), used by the coding agent's startup watchdog to name the in-flight phase of a stalled startup. ### Changed +- Changed `prompt.compile()` to cache compiled templates by the raw template string so repeated calls reuse the same compiled function without re-disambiguating - `Snowflake.formatParts` packs the id as a single 64-bit BigInt hex format instead of stitching four 16-bit segments (simpler and ~1.7x faster), and `getTimestamp` extracts via exact double arithmetic instead of a BigInt round-trip. Output is bit-identical. +### Fixed + +- Fixed `prompt.format()` so ASCII symbol replacements such as `-->` and `!=` still run on lines containing a closing HTML comment token when not inside a comment +- `omp --help` now loads only the requested command module instead of the entire command table, so an unrelated command whose import graph hangs or crashes can no longer take down every per-command help invocation. ## [15.10.8] - 2026-06-09 ### Removed diff --git a/packages/utils/src/cli.ts b/packages/utils/src/cli.ts index 4cbd41ead..c747d20d6 100644 --- a/packages/utils/src/cli.ts +++ b/packages/utils/src/cli.ts @@ -9,8 +9,25 @@ * - Lazy command imports (only the invoked command is loaded) * - Typed `this.parse()` output matching oclif's API shape */ +import * as fs from "node:fs"; import { parseArgs as nodeParseArgs } from "node:util"; +/** + * Streaming startup marker, enabled by `PI_DEBUG_STARTUP`. Local copy of + * `logger.startupMarker` so the minimal `--version`/bootstrap import graph + * stays free of the winston-backed logger module. Synchronous on purpose: + * a command module whose import hangs (dlopen, fs on a dead mount) must + * still leave its `:start` marker behind. + */ +function startupMarker(text: string): void { + if (!process.env.PI_DEBUG_STARTUP) return; + try { + fs.writeSync(2, `[startup] ${text}\n`); + } catch { + // stderr unavailable; markers are best-effort + } +} + // --------------------------------------------------------------------------- // Flag & Arg descriptors // --------------------------------------------------------------------------- @@ -392,14 +409,14 @@ export async function run(opts: RunOptions): Promise { return; } - // Per-command help + // Per-command help: load only the requested command. Loading the full + // command table here would make `omp --help` hang or crash whenever + // any *unrelated* command module misbehaves at import time. if (commandArgv.includes("--help") || commandArgv.includes("-h")) { - const config = await loadAllCommands(opts); - // Resolve aliases for help too const entry = findEntry(opts.commands, commandId); - const Cmd = entry ? config.commands.get(entry.name) : undefined; - if (Cmd) { - renderCommandHelp(bin, entry!.name, Cmd); + if (entry) { + const Cmd = await loadEntry(entry); + renderCommandHelp(bin, entry.name, Cmd); } else { process.stderr.write(`Unknown command: ${commandId}\n`); } @@ -415,16 +432,24 @@ export async function run(opts: RunOptions): Promise { return; } - const Cmd = await entry.load(); + const Cmd = await loadEntry(entry); const config: CliConfig = { bin, version, commands: new Map([[entry.name, Cmd]]) }; const instance = new Cmd(commandArgv, config); await instance.run(); } +/** Load one command module, leaving streaming markers around the import. */ +async function loadEntry(entry: CommandEntry): Promise { + startupMarker(`cli:load:${entry.name}:start`); + const Cmd = await entry.load(); + startupMarker(`cli:load:${entry.name}:done`); + return Cmd; +} + /** Resolve all command loaders for help/alias display. */ async function loadAllCommands(opts: RunOptions): Promise { const commands = new Map(); - const loaded = await Promise.all(opts.commands.map(async e => [e.name, await e.load()] as const)); + const loaded = await Promise.all(opts.commands.map(async e => [e.name, await loadEntry(e)] as const)); for (const [name, Cmd] of loaded) { commands.set(name, Cmd); } diff --git a/packages/utils/src/logger.ts b/packages/utils/src/logger.ts index 1591e1620..124a4429e 100644 --- a/packages/utils/src/logger.ts +++ b/packages/utils/src/logger.ts @@ -47,25 +47,30 @@ function jsonReplacer(_key: string, value: unknown): unknown { return value; } -/** Custom format that includes pid and flattens metadata */ -const logFormat = winston.format.combine( - winston.format.timestamp({ format: "YYYY-MM-DDTHH:mm:ss.SSSZ" }), - winston.format.printf(({ timestamp, level, message, ...meta }) => { - const entry: Record = { - timestamp, - level, - pid: process.pid, - message, - }; - // Flatten metadata into entry - for (const [key, value] of Object.entries(meta)) { - if (key !== "level" && key !== "timestamp" && key !== "message") { - entry[key] = value; +/** Custom format that includes pid and flattens metadata; built on first use. */ +let logFormat: winston.Logform.Format | undefined; + +function getLogFormat(): winston.Logform.Format { + logFormat ??= winston.format.combine( + winston.format.timestamp({ format: "YYYY-MM-DDTHH:mm:ss.SSSZ" }), + winston.format.printf(({ timestamp, level, message, ...meta }) => { + const entry: Record = { + timestamp, + level, + pid: process.pid, + message, + }; + // Flatten metadata into entry + for (const [key, value] of Object.entries(meta)) { + if (key !== "level" && key !== "timestamp" && key !== "message") { + entry[key] = value; + } } - } - return JSON.stringify(entry, jsonReplacer); - }), -); + return JSON.stringify(entry, jsonReplacer); + }), + ); + return logFormat; +} /** Build a rotating file transport, materializing the target directory lazily. */ function makeFileTransport(dir?: string): winston.transport { @@ -80,17 +85,35 @@ function makeFileTransport(dir?: string): winston.transport { } function makeConsoleTransport(): winston.transport { - return new winston.transports.Console({ format: logFormat }); + return new winston.transports.Console({ format: getLogFormat() }); } -/** The winston logger instance. Default: file ON (TUI-safe), console OFF. */ -const winstonLogger = winston.createLogger({ - level: "debug", - format: logFormat, - transports: [makeFileTransport()], - // Don't exit on error - logging failures shouldn't crash the app - exitOnError: false, -}); +/** + * Desired transport configuration, applied when the winston logger is built. + * Default: file ON (TUI-safe), console OFF. + */ +let transportOpts: { console?: boolean; file?: boolean | string } = { file: true }; + +/** The winston logger instance, created lazily on first log emission. */ +let winstonLogger: winston.Logger | undefined; + +function buildTransports(opts: { console?: boolean; file?: boolean | string }): winston.transport[] { + const transports: winston.transport[] = []; + if (opts.file) transports.push(makeFileTransport(typeof opts.file === "string" ? opts.file : undefined)); + if (opts.console) transports.push(makeConsoleTransport()); + return transports; +} + +function getWinstonLogger(): winston.Logger { + winstonLogger ??= winston.createLogger({ + level: "debug", + format: getLogFormat(), + transports: buildTransports(transportOpts), + // Don't exit on error - logging failures shouldn't crash the app + exitOnError: false, + }); + return winstonLogger; +} /** * Replace the active log transports. Pass `console: true, file: false` for @@ -98,11 +121,10 @@ const winstonLogger = winston.createLogger({ * logs piped into a process supervisor instead of the rotating file. */ export function setTransports(opts: { console?: boolean; file?: boolean | string }): void { + transportOpts = opts; + if (!winstonLogger) return; // applied lazily when the logger is first built winstonLogger.clear(); - if (opts.file) { - winstonLogger.add(makeFileTransport(typeof opts.file === "string" ? opts.file : undefined)); - } - if (opts.console) winstonLogger.add(makeConsoleTransport()); + for (const transport of buildTransports(opts)) winstonLogger.add(transport); } /** @@ -112,7 +134,7 @@ export function setTransports(opts: { console?: boolean; file?: boolean | string */ export function error(message: string, context?: Record): void { try { - winstonLogger.error(message, context); + getWinstonLogger().error(message, context); } catch { // Silently ignore logging failures } @@ -125,7 +147,7 @@ export function error(message: string, context?: Record): void */ export function warn(message: string, context?: Record): void { try { - winstonLogger.warn(message, context); + getWinstonLogger().warn(message, context); } catch { // Silently ignore logging failures } @@ -138,7 +160,7 @@ export function warn(message: string, context?: Record): void { */ export function info(message: string, context?: Record): void { try { - winstonLogger.info(message, context); + getWinstonLogger().info(message, context); } catch { // Silently ignore logging failures } @@ -151,12 +173,29 @@ export function info(message: string, context?: Record): void { */ export function debug(message: string, context?: Record): void { try { - winstonLogger.debug(message, context); + getWinstonLogger().debug(message, context); } catch { // Silently ignore logging failures } } +/** + * Streaming startup markers, enabled by `PI_DEBUG_STARTUP`. Unlike the + * PI_TIMING tree (printed only after startup completes), these write one + * synchronous stderr line as each phase begins/ends, so a hard hang still + * shows the last phase that started. `fs.writeSync(2)` is used deliberately: + * it cannot be reordered or buffered past a synchronous block of the event + * loop (dlopen, sync fs on a dead mount, spawnSync). + */ +export function startupMarker(text: string): void { + if (!process.env.PI_DEBUG_STARTUP) return; + try { + fs.writeSync(2, `[startup] ${text}\n`); + } catch { + // stderr unavailable; markers are best-effort + } +} + const LOGGED_TIMING_THRESHOLD_MS = 0.5; interface Span { @@ -329,6 +368,29 @@ export function endTiming(): void { gRecordTimings = false; } +/** + * Ops of the currently-open span chain (root → deepest), following the most + * recently started unfinished child at each level. Lets a startup watchdog + * name the phase a stalled startup is stuck in. + */ +export function openSpanPath(): string[] { + const ops: string[] = []; + let node = gRootSpan; + while (node) { + let next: Span | undefined; + for (let i = node.children.length - 1; i >= 0; i--) { + if (node.children[i].end === undefined) { + next = node.children[i]; + break; + } + } + if (!next) break; + ops.push(next.op); + node = next; + } + return ops; +} + function durationOf(span: Span): number { if (span.point || span.end === undefined) return 0; return span.end - span.start; @@ -550,33 +612,51 @@ function isParallel(span: Span): boolean { export function time(op: string): void; export function time(op: string, fn: (...args: A) => T, ...args: A): T; export function time(op: string, fn?: (...args: A) => T, ...args: A): T | undefined { - if (!gRecordTimings || !gRootSpan) { - if (fn === undefined) return undefined as T; - return fn(...args); - } - - const parent = spanStorage.getStore() ?? gRootSpan; - const span: Span = { op, start: performance.now(), parent, children: [] }; - parent.children.push(span); + const recording = gRecordTimings && gRootSpan !== undefined; if (fn === undefined) { - span.end = span.start; - span.point = true; + startupMarker(op); + if (!recording) return undefined as T; + const parent = spanStorage.getStore() ?? gRootSpan!; + const now = performance.now(); + parent.children.push({ op, start: now, end: now, parent, children: [], point: true }); return undefined as T; } - const finish = (): void => { - span.end = performance.now(); + if (!recording && !process.env.PI_DEBUG_STARTUP) { + return fn(...args); + } + + startupMarker(`${op}:start`); + let span: Span | undefined; + if (recording) { + const parent = spanStorage.getStore() ?? gRootSpan!; + span = { op, start: performance.now(), parent, children: [] }; + parent.children.push(span); + } + + const finish = (ok: boolean): void => { + if (span) span.end = performance.now(); + startupMarker(ok ? `${op}:done` : `${op}:fail`); }; try { - const result = spanStorage.run(span, () => fn(...args)); + const result = span ? spanStorage.run(span, () => fn(...args)) : fn(...args); if (isPromise(result)) { - return result.finally(finish) as T; + return result.then( + value => { + finish(true); + return value; + }, + error => { + finish(false); + throw error; + }, + ) as T; } - finish(); + finish(true); return result; } catch (error) { - finish(); + finish(false); throw error; } } diff --git a/packages/utils/src/prompt.ts b/packages/utils/src/prompt.ts index c2845d26b..c175c5e78 100644 --- a/packages/utils/src/prompt.ts +++ b/packages/utils/src/prompt.ts @@ -13,14 +13,53 @@ export interface PromptFormatOptions { // Opening XML tag (not self-closing, not closing) const OPENING_XML = /^<([a-z_-]+)(?:\s+[^>]*)?>$/; -// Closing XML tag -const CLOSING_XML = /^<\/([a-z_-]+)>$/; -// Handlebars block end: {{/if}}, {{/has}}, {{/list}}, etc. -const CLOSING_HBS = /^\{\{\//; + +/** + * Closing XML tag matcher, manual equivalent of `/^<\/([a-z_-]+)>$/` — avoids a + * RegExp exec (and match array allocation) per `<`-prefixed line. Caller + * guarantees `s` starts ` */) return null; + for (let j = 2; j < n - 1; j++) { + const c = s.charCodeAt(j); + if (!((c >= 97 /* a */ && c <= 122) /* z */ || c === 45 /* - */ || c === 95) /* _ */) return null; + } + return s.slice(2, n - 1); +} + +/** + * Manual equivalent of {@link OPENING_XML}. Caller guarantees `s` starts with + * `<` but not ` */) return null; + let j = 1; + while (j < n - 1) { + const c = s.charCodeAt(j); + if ((c >= 97 /* a */ && c <= 122) /* z */ || c === 45 /* - */ || c === 95 /* _ */) j++; + else break; + } + if (j === 1) return null; + if (j === n - 1) return s.slice(1, j); // `` + const c = s.charCodeAt(j); + if (c !== 32 /* space */ && c !== 9 /* tab */) { + if (c < 128) return null; + const match = OPENING_XML.exec(s); + return match ? match[1] : null; + } + // `\s+[^>]*>$` ⇔ no further `>` before the final char. + return s.indexOf(">", j + 1) === n - 1 ? s.slice(1, j) : null; +} // Table row const TABLE_ROW = /^\|.*\|$/; // Table separator (|---|---|) const TABLE_SEP = /^\|[-:\s|]+\|$/; +// Any non-whitespace char — blank-line check without allocating a trimmed copy +const NON_BLANK = /\S/; /** * RFC 2119 keywords (plus project aliases NEVER/AVOID) wrapped in markdown bold @@ -28,6 +67,19 @@ const TABLE_SEP = /^\|[-:\s|]+\|$/; */ const RFC2119_BOLD = /\*\*(MUST NOT|SHOULD NOT|RECOMMENDED|REQUIRED|OPTIONAL|SHOULD|MUST|MAY|NEVER|AVOID)\*\*/g; +/** + * Fast pre-check for {@link normalizeRfc2119}: a line that lacks every one of + * these substrings is untouched by all three replacements, so the + * split/replace/join machinery can be skipped entirely. + */ +const RFC2119_GUARD = /\*\*(?:MUST|SHOULD|RECOMMENDED|REQUIRED|OPTIONAL|MAY|NEVER|AVOID)|MUST NOT|SHOULD NOT/; +const MUST_NOT = /\bMUST NOT\b/g; +const SHOULD_NOT = /\bSHOULD NOT\b/g; + +function applyRfc2119(text: string): string { + return text.replace(RFC2119_BOLD, "$1").replace(MUST_NOT, "NEVER").replace(SHOULD_NOT, "AVOID"); +} + /** * Normalize RFC 2119 markers per project convention: * - Strip `**KEYWORD**` bold (visual noise, no semantics). @@ -35,12 +87,11 @@ const RFC2119_BOLD = /\*\*(MUST NOT|SHOULD NOT|RECOMMENDED|REQUIRED|OPTIONAL|SHO * Skips spans inside inline code (`` `…` ``) so alias definitions can be quoted literally. */ function normalizeRfc2119(line: string): string { + if (!RFC2119_GUARD.test(line)) return line; + if (!line.includes("`")) return applyRfc2119(line); const segments = line.split("`"); for (let i = 0; i < segments.length; i += 2) { - segments[i] = segments[i] - .replace(RFC2119_BOLD, "$1") - .replace(/\bMUST NOT\b/g, "NEVER") - .replace(/\bSHOULD NOT\b/g, "AVOID"); + segments[i] = applyRfc2119(segments[i]); } return segments.join("`"); } @@ -73,19 +124,31 @@ type HtmlCommentState = { inHtmlComment: boolean; }; +// Single-pass alternation equivalent to the former chain of seven .replace() +// calls. Alternative order mirrors the old sequential order (`<->` before +// `->`/`<-`), and every replacement emits a non-ASCII char, so one pass +// produces byte-identical output to the sequential passes. +const ASCII_SYMBOLS = /\.{3}|<->|->|<-|!=|<=|>=/g; +const ASCII_SYMBOL_REPLACEMENTS: Record = { + "...": "…", + "<->": "↔", + "->": "→", + "<-": "←", + "!=": "≠", + "<=": "≤", + ">=": "≥", +}; +const replaceAsciiSymbol = (match: string): string => ASCII_SYMBOL_REPLACEMENTS[match]; + function replaceCommonAsciiSymbols(line: string): string { - return line - .replace(/\.{3}/g, "…") - .replace(/<->/g, "↔") - .replace(/->/g, "→") - .replace(/<-/g, "←") - .replace(/!=/g, "≠") - .replace(/<=/g, "≤") - .replace(/>=/g, "≥"); + return line.replace(ASCII_SYMBOLS, replaceAsciiSymbol); } function replaceCommonAsciiSymbolsOutsideHtmlComments(line: string, state: HtmlCommentState): string { - if (!state.inHtmlComment && !line.includes(HTML_COMMENT_OPEN) && !line.includes(HTML_COMMENT_CLOSE)) { + // When not inside a comment, a line without ``: the slow path would hit openIndex === -1 and replace + // the whole line identically. + if (!state.inHtmlComment && !line.includes(HTML_COMMENT_OPEN)) { return replaceCommonAsciiSymbols(line); } @@ -133,86 +196,111 @@ export function format(content: string, options: PromptFormatOptions = {}): stri } = options; const isPreRender = renderPhase === "pre-render"; const lines = content.split("\n"); - const result: string[] = []; + const result: string[] = new Array(lines.length); + let n = 0; // logical length of `result` (pops are n--) let inCodeBlock = false; const htmlCommentState: HtmlCommentState = { inHtmlComment: false }; const topLevelTags: string[] = []; for (let i = 0; i < lines.length; i++) { - let line = lines[i].trimEnd(); - let trimmedStart = line.trimStart(); - if (trimmedStart.startsWith("```") || trimmedStart.startsWith("~~~")) { + const raw = lines[i]; + // charCode fast paths: only pay for trimEnd when the last char might be + // whitespace (<= 0x20 ASCII ws/controls, >= 0x80 unicode ws). Untouched + // lines are pushed as the original string — no allocation. + const last = raw.charCodeAt(raw.length - 1); + let line = last <= 32 || last >= 128 ? raw.trimEnd() : raw; + // Locate the first non-whitespace char without allocating a trimStart + // copy; `s` is the indent width, `first` the char code there (NaN when + // the line is blank). + let s = 0; + let first = line.charCodeAt(0); + while (first === 32 /* space */ || first === 9 /* tab */) first = line.charCodeAt(++s); + if (first >= 128) { + // Possible unicode leading whitespace — defer to trimStart for exactness. + s = line.length - line.trimStart().length; + first = line.charCodeAt(s); + } + + if ((first === 96 /* ` */ || first === 126) /* ~ */ && (line.startsWith("```", s) || line.startsWith("~~~", s))) { inCodeBlock = !inCodeBlock; - result.push(line); + result[n++] = line; continue; } if (inCodeBlock) { - result.push(line); + result[n++] = line; continue; } if (replaceAsciiSymbols) { - line = replaceCommonAsciiSymbolsOutsideHtmlComments(line, htmlCommentState); - } - trimmedStart = line.trimStart(); - const trimmed = line.trim(); - - const isOpeningXml = OPENING_XML.test(trimmedStart) && !trimmedStart.endsWith("/>"); - if (isOpeningXml && line.length === trimmedStart.length) { - const match = OPENING_XML.exec(trimmedStart); - if (match) topLevelTags.push(match[1]); - } - - const closingMatch = CLOSING_XML.exec(trimmedStart); - if (closingMatch) { - const tagName = closingMatch[1]; - if (topLevelTags.length > 0 && topLevelTags[topLevelTags.length - 1] === tagName) { - topLevelTags.pop(); + const replaced = replaceCommonAsciiSymbolsOutsideHtmlComments(line, htmlCommentState); + if (replaced !== line) { + line = replaced; + s = 0; + first = line.charCodeAt(0); + while (first === 32 || first === 9) first = line.charCodeAt(++s); + if (first >= 128) { + s = line.length - line.trimStart().length; + first = line.charCodeAt(s); + } + } + } + + let isClosingLine = false; + if (first === 60 /* < */) { + const trimmedStart = s === 0 ? line : line.slice(s); + if (trimmedStart.charCodeAt(1) === 47 /* / */) { + const tagName = closingTagName(trimmedStart); + if (tagName !== null) { + isClosingLine = true; + if (topLevelTags.length > 0 && topLevelTags[topLevelTags.length - 1] === tagName) { + topLevelTags.pop(); + } + } + } else if (s === 0 && !trimmedStart.endsWith("/>")) { + const tagName = openingTagName(trimmedStart); + if (tagName !== null) topLevelTags.push(tagName); + } + } else if (first === 124 /* | */) { + const trimmedStart = s === 0 ? line : line.slice(s); + if (TABLE_SEP.test(trimmedStart)) { + line = `${line.slice(0, s)}${compactTableSep(trimmedStart)}`; + } else if (TABLE_ROW.test(trimmedStart)) { + line = `${line.slice(0, s)}${compactTableRow(trimmedStart)}`; } - } else if (isPreRender && trimmedStart.startsWith("{{")) { - /* keep indentation as-is in pre-render for Handlebars markers */ - } else if (TABLE_SEP.test(trimmedStart)) { - const leadingWhitespace = line.slice(0, line.length - trimmedStart.length); - line = `${leadingWhitespace}${compactTableSep(trimmedStart)}`; - } else if (TABLE_ROW.test(trimmedStart)) { - const leadingWhitespace = line.slice(0, line.length - trimmedStart.length); - line = `${leadingWhitespace}${compactTableRow(trimmedStart)}`; } if (shouldNormalizeRfc2119) { line = normalizeRfc2119(line); } - if (trimmed === "") { - const nextLine = lines[i + 1]?.trim() ?? ""; + if (s >= line.length) { + // Blank line (`line` carries no trailing whitespace, so it is ""). + const next = lines[i + 1]; // Strip any run of 2+ consecutive blank lines entirely; preserve a single blank. - if (nextLine === "") { - while (result.length > 0 && result[result.length - 1].trim() === "") { - result.pop(); - } - while (i + 1 < lines.length && lines[i + 1].trim() === "") i++; + if (next === undefined || next.length === 0 || !NON_BLANK.test(next)) { + while (n > 0 && result[n - 1].length === 0) n--; + let j = i + 1; + while (j < lines.length && (lines[j].length === 0 || !NON_BLANK.test(lines[j]))) j++; + i = j - 1; continue; } - const prevLine = result[result.length - 1]?.trim() ?? ""; - if (prevLine === "") { + if (n === 0 || result[n - 1].length === 0) { continue; } } - if (CLOSING_XML.test(trimmed) || (isPreRender && CLOSING_HBS.test(trimmed))) { - while (result.length > 0 && result[result.length - 1].trim() === "") { - result.pop(); - } + // CLOSING_HBS (`/^\{\{\//`) ⇔ startsWith("{{/") at the indent offset. + if (isClosingLine || (isPreRender && first === 123 /* { */ && line.startsWith("{{/", s))) { + while (n > 0 && result[n - 1].length === 0) n--; } - result.push(line); + result[n++] = line; } - while (result.length > 0 && result[result.length - 1].trim() === "") { - result.pop(); - } + while (n > 0 && result[n - 1].length === 0) n--; + result.length = n; return result.join("\n"); } @@ -454,13 +542,14 @@ function disambiguateClosingBraces(template: string): string { const compiledTemplateCache = new Map string>(); export function compile(template: string): (context: TemplateContext) => string { - const disambiguated = disambiguateClosingBraces(template); - const cached = compiledTemplateCache.get(disambiguated); + // Keyed on the raw template so repeat renders skip disambiguateClosingBraces + // (a full-template regex pass) as well as the Handlebars compile. + const cached = compiledTemplateCache.get(template); if (cached) return cached; - const compiled = handlebars.compile(disambiguated, { noEscape: true, strict: false }) as ( + const compiled = handlebars.compile(disambiguateClosingBraces(template), { noEscape: true, strict: false }) as ( context: TemplateContext, ) => string; - compiledTemplateCache.set(disambiguated, compiled); + compiledTemplateCache.set(template, compiled); return compiled; } diff --git a/packages/utils/test/cli-help.test.ts b/packages/utils/test/cli-help.test.ts new file mode 100644 index 000000000..0992fbecf --- /dev/null +++ b/packages/utils/test/cli-help.test.ts @@ -0,0 +1,42 @@ +import { describe, expect, it, spyOn } from "bun:test"; +import { Command, type CommandEntry, Flags, run } from "@oh-my-pi/pi-utils/cli"; + +class GoodCommand extends Command { + static description = "prints good things"; + static flags = { + verbose: Flags.boolean({ description: "be loud" }), + }; + async run(): Promise {} +} + +describe("run() per-command help", () => { + // Contract: `omp --help` must load only the requested command module. + // Loading the whole table would let any unrelated command whose import + // hangs or crashes take down every per-command help invocation. + it("loads only the requested command", async () => { + let brokenLoads = 0; + const commands: CommandEntry[] = [ + { name: "good", load: async () => GoodCommand }, + { + name: "broken", + load: async () => { + brokenLoads++; + throw new Error("import-time crash"); + }, + }, + ]; + const writes: string[] = []; + const stdoutSpy = spyOn(process.stdout, "write").mockImplementation(chunk => { + writes.push(String(chunk)); + return true; + }); + try { + await run({ bin: "omp", version: "0.0.0", argv: ["good", "--help"], commands }); + } finally { + stdoutSpy.mockRestore(); + } + expect(brokenLoads).toBe(0); + expect(writes.join("")).toContain("prints good things"); + expect(writes.join("")).toContain("--verbose"); + }); +}); diff --git a/packages/utils/test/logger-startup.test.ts b/packages/utils/test/logger-startup.test.ts new file mode 100644 index 000000000..9b2ac9554 --- /dev/null +++ b/packages/utils/test/logger-startup.test.ts @@ -0,0 +1,95 @@ +import { describe, expect, it, spyOn } from "bun:test"; +import * as fs from "node:fs"; +import * as logger from "@oh-my-pi/pi-utils/logger"; + +/** Run `fn` with PI_DEBUG_STARTUP set, capturing `[startup]` stderr markers. */ +function withMarkerCapture(fn: () => T): { result: T; markers: string[] } { + const prev = process.env.PI_DEBUG_STARTUP; + process.env.PI_DEBUG_STARTUP = "1"; + const markers: string[] = []; + const writeSpy = spyOn(fs, "writeSync").mockImplementation(((_fd: number, data: string) => { + const text = String(data); + if (text.startsWith("[startup]")) markers.push(text.trimEnd()); + return text.length; + }) as typeof fs.writeSync); + try { + return { result: fn(), markers }; + } finally { + writeSpy.mockRestore(); + if (prev === undefined) { + delete process.env.PI_DEBUG_STARTUP; + } else { + process.env.PI_DEBUG_STARTUP = prev; + } + } +} + +describe("PI_DEBUG_STARTUP streaming markers", () => { + // Contract: with PI_DEBUG_STARTUP set, every logger.time phase leaves a + // synchronous `:start` marker before running — so a phase that hangs the + // process forever is still identified by the last marker on stderr. This + // must work without startTiming() (markers are independent of PI_TIMING). + it("brackets a phase with start/done markers", () => { + const { result, markers } = withMarkerCapture(() => logger.time("phase:test", () => 42)); + expect(result).toBe(42); + expect(markers).toEqual(["[startup] phase:test:start", "[startup] phase:test:done"]); + }); + + it("marks a throwing phase as failed and rethrows", () => { + const { markers } = withMarkerCapture(() => { + expect(() => + logger.time("phase:boom", () => { + throw new Error("boom"); + }), + ).toThrow("boom"); + }); + expect(markers).toEqual(["[startup] phase:boom:start", "[startup] phase:boom:fail"]); + }); + + it("emits a single marker for point spans", () => { + const { markers } = withMarkerCapture(() => logger.time("phase:point")); + expect(markers).toEqual(["[startup] phase:point"]); + }); + + it("emits nothing when PI_DEBUG_STARTUP is unset", () => { + const prev = process.env.PI_DEBUG_STARTUP; + delete process.env.PI_DEBUG_STARTUP; + const writes: string[] = []; + const writeSpy = spyOn(fs, "writeSync").mockImplementation(((_fd: number, data: string) => { + writes.push(String(data)); + return String(data).length; + }) as typeof fs.writeSync); + try { + expect(logger.time("phase:silent", () => "ok")).toBe("ok"); + } finally { + writeSpy.mockRestore(); + if (prev !== undefined) process.env.PI_DEBUG_STARTUP = prev; + } + expect(writes.filter(w => w.startsWith("[startup]"))).toEqual([]); + }); +}); + +describe("openSpanPath", () => { + // Contract: while a startup phase is in flight, openSpanPath names the + // chain root → deepest open span. The startup watchdog prints this to tell + // the user which phase a stalled startup is stuck in. + it("names the deepest in-flight span and clears once settled", async () => { + logger.startTiming(); + try { + const gate = Promise.withResolvers(); + const running = logger.time("outer", async () => { + await logger.time("inner", () => gate.promise); + }); + expect(logger.openSpanPath()).toEqual(["outer", "inner"]); + gate.resolve(); + await running; + expect(logger.openSpanPath()).toEqual([]); + } finally { + logger.endTiming(); + } + }); + + it("returns empty when timing is not recording", () => { + expect(logger.openSpanPath()).toEqual([]); + }); +}); diff --git a/packages/utils/test/prompt.test.ts b/packages/utils/test/prompt.test.ts new file mode 100644 index 000000000..494b8d323 --- /dev/null +++ b/packages/utils/test/prompt.test.ts @@ -0,0 +1,96 @@ +import { describe, expect, it } from "bun:test"; +import * as prompt from "@oh-my-pi/pi-utils/prompt"; + +const FULL = { renderPhase: "pre-render", replaceAsciiSymbols: true, normalizeRfc2119: true } as const; + +describe("format: ascii symbol replacement", () => { + it("replaces all seven symbols in one line", () => { + expect(prompt.format("a -> b <- c <-> d != e <= f >= g ... h", FULL)).toBe("a → b ← c ↔ d ≠ e ≤ f ≥ g … h"); + }); + + it("prioritizes <-> over -> and <- on overlapping input", () => { + // `<=->` must resolve as `<=` + `->`, and `<->` must win over its halves. + expect(prompt.format("<=-> <-> ->= <-- -->x", FULL)).toBe("≤→ ↔ →= ←- -→x"); + }); + + it("consumes ellipsis runs greedily in threes", () => { + expect(prompt.format("....... ..", FULL)).toBe("……. .."); + expect(prompt.format("......", FULL)).toBe("……"); + expect(prompt.format("....", FULL)).toBe("…."); + }); + + it("skips replacements inside html comments, including multi-line state", () => { + expect(prompt.format(" c -> d", FULL)).toBe(" c → d"); + expect(prompt.format("\nC -> D", FULL)).toBe("\nC → D"); + }); + + it("replaces symbols on a line containing --> but no opener", () => { + expect(prompt.format("x --> y != z", FULL)).toBe("x -→ y ≠ z"); + }); + + it("leaves code fences untouched", () => { + const input = "```\na -> b\n```"; + expect(prompt.format(input, FULL)).toBe(input); + }); +}); + +describe("format: rfc 2119 normalization", () => { + it("strips bold and aliases MUST NOT / SHOULD NOT outside inline code", () => { + expect(prompt.format("You **MUST** act. You **MUST NOT** stall. SHOULD NOT applies.", FULL)).toBe( + "You MUST act. You NEVER stall. AVOID applies.", + ); + }); + + it("preserves keywords inside inline code spans", () => { + expect(prompt.format("alias `MUST NOT` means MUST NOT", FULL)).toBe("alias `MUST NOT` means NEVER"); + }); + + it("leaves non-keyword bold alone", () => { + expect(prompt.format("**bold** stays **bold**", FULL)).toBe("**bold** stays **bold**"); + }); +}); + +describe("format: structure", () => { + it("compacts table rows and separators, preserving indent and alignment", () => { + expect(prompt.format("| a | b |\n|:--- | --:|\n| c | d |")).toBe("|a|b|\n|:---|---:|\n|c|d|"); + expect(prompt.format(" | a | b |")).toBe(" |a|b|"); + }); + + it("collapses runs of 2+ blank lines and trims boundary blanks", () => { + expect(prompt.format("\n\na\n\n\nb\n \n\t\nc\n\n")).toBe("a\nb\nc"); + expect(prompt.format("a\n\nb")).toBe("a\n\nb"); + }); + + it("drops a single blank line before a closing xml tag", () => { + expect(prompt.format("\nbody\n\n")).toBe("\nbody\n"); + }); + + it("does not treat self-closing or attribute-laden non-tags as block tags", () => { + // ` c>` is not an opening tag (inner `>`); blank before `` still pops. + expect(prompt.format('\nbody\n\n')).toBe('\nbody\n'); + expect(prompt.format("\nx")).toBe("\nx"); + }); + + it("keeps blank handling inside code fences verbatim", () => { + const input = "```\na\n\n\n\nb\n```"; + expect(prompt.format(input)).toBe(input); + }); + + it("pops blanks before handlebars block closers only in pre-render", () => { + expect(prompt.format("{{#if x}}\nbody\n\n{{/if}}", { renderPhase: "pre-render" })).toBe( + "{{#if x}}\nbody\n{{/if}}", + ); + expect(prompt.format("body\n\n{{/if}}", { renderPhase: "post-render" })).toBe("body\n\n{{/if}}"); + }); +}); + +describe("compile cache", () => { + it("returns the identical compiled function for repeat compiles of the same template", () => { + const template = "Hello {{name}} {{#if x}}yes{{/if}}"; + expect(prompt.compile(template)).toBe(prompt.compile(template)); + }); + + it("renders templates with 3+ closing braces unambiguously", () => { + expect(prompt.render("{{#if a}}{ {{b}}}{{/if}}", { a: true, b: "v" })).toBe("{ v}"); + }); +});