diff --git a/CHANGELOG.md b/CHANGELOG.md index 2a8b93a..8b5d9b9 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,6 +7,9 @@ project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.html). ## [Unreleased] +- Bounded metadata-only request/tool traces for durable workers, with paged retrieval, repeated-read fingerprints, usage coverage and phase timings. Benchmarks retain trace artifacts. +- Opt-in token/time reserves stop restricted OpenCode workers, confirm idle, and verify their patches before the hard limit. Failed checks use the existing bounded repair; hard budgets, errors, cancellation and ownership remain authoritative. + ### Added - Optional scoped OpenCode workers using the supported custom-agent API: model-specific instructions, local tools, preserved repository rules, no automatic skills catalog, and a fixed 24-step limit. The full `standard` agent remains the default; `focused` adds an experimental compact prompt. - Separate engine uncached/cache-read/cache-write/reasoning/request metrics, accumulated across repairs. Paired repository-regression benchmark with withheld evaluator checks and a real-engine local request-size probe. diff --git a/benchmarks/results/2026-09-21/checkpoint-smoke.json b/benchmarks/results/2026-09-21/checkpoint-smoke.json new file mode 100644 index 0000000..50ab83b --- /dev/null +++ b/benchmarks/results/2026-09-21/checkpoint-smoke.json @@ -0,0 +1,97 @@ +{ + "testedAt": "2026-09-21T07:58:17.141Z", + "engineVersion": "1.18.31", + "scope": "Real installed engine, synthetic local inference; verifies stop-before-check, not coding quality or token savings.", + "requests": 2, + "checkedIdle": true, + "status": "completed", + "completion": { + "source": "checkpoint", + "checkpoint": { + "requested": true, + "confirmed": true, + "trigger": "time" + } + }, + "usage": { + "inTokens": 100, + "outTokens": 5, + "estimated": false, + "available": true, + "uncachedInTokens": 100, + "cacheReadTokens": 0, + "cacheWriteTokens": 0, + "reasoningTokens": 0, + "modelRequests": 2 + }, + "elapsedMs": 5075, + "trace": { + "version": 1, + "requestCoverage": "observed", + "coverage": "Observed engine assistant messages and tool events; provider retries, child sessions and full request payloads are not captured.", + "summary": { + "requestCoverage": "observed", + "requests": 2, + "requestsWithUsage": 1, + "tools": 1, + "repeatedReads": 0, + "toolOutputBytes": 24, + "requestsWithTiming": 2, + "toolsWithTiming": 1, + "cumulativeAssistantMs": 4679, + "cumulativeToolMs": 6, + "verificationMs": 3, + "executionMs": 5074, + "discardedEvents": 0 + }, + "requests": [ + { + "id": "r1", + "startedAt": 1789977492445, + "completedAt": 1789977493049, + "turn": 1, + "model": "fixture/coder", + "usage": { + "input": 100, + "output": 5, + "reasoning": 0, + "cacheRead": 0, + "cacheWrite": 0 + }, + "usageReported": true, + "elapsedMs": 604 + }, + { + "id": "r2", + "startedAt": 1789977493050, + "completedAt": 1789977497125, + "turn": 1, + "model": "fixture/coder", + "usage": { + "input": 0, + "output": 0, + "reasoning": 0, + "cacheRead": 0, + "cacheWrite": 0 + }, + "usageReported": false, + "failed": true, + "elapsedMs": 4075 + } + ], + "tools": [ + { + "id": "t1", + "startedAt": 1789977493037, + "completedAt": 1789977493043, + "turn": 1, + "name": "write", + "request": "r1", + "fingerprint": "87a2872fa824640d4bc65bf2", + "ok": true, + "outputBytes": 24, + "elapsedMs": 6 + } + ] + } +} diff --git a/docs/coding-benchmarks.md b/docs/coding-benchmarks.md index d4d474c..f6e7d79 100644 --- a/docs/coding-benchmarks.md +++ b/docs/coding-benchmarks.md @@ -44,7 +44,7 @@ Task/profile ordering alternates between repetitions to reduce systematic order ## Read the report -The JSON records the source hash, engine version, model, preflight, per-task results, patches, verification, usage and elapsed time. Companion `.patches/` files make solutions inspectable. Temporary service/worktrees are removed after complete runs. A transient read timeout is retried without replaying mutations. After an interruption or unrecoverable transport error, the service is stopped and an atomic checkpoint plus worktrees are retained. Resume with `node scripts/benchmark-coding.js --resume `; existing job IDs are recovered, interrupted execution is not silently replayed, and an already recorded application is verified rather than applied again. Logical job failures remain scored failures. Use `--cases` with comma-separated task IDs for a smaller diagnostic run. The report has an explicit `complete` flag and unfinished IDs. The runner exits nonzero if any task is unaccepted or unfinished, but retains the report so failures remain part of the comparison. +The JSON records the source hash, engine version, model, preflight, per-task results, patches, verification, usage and elapsed time. Companion `.patches/` files make solutions inspectable. New runs also retain `.traces/` metadata with per-message usage, tool timing/output sizes, and repeated-read fingerprints. Timings include queue, preparation, execution and collection; engine message lifetimes are not pure inference time. Temporary service/worktrees are removed after complete runs. A transient read timeout is retried without replaying mutations. After an interruption or unrecoverable transport error, the service is stopped and an atomic checkpoint plus worktrees are retained. Resume with `node scripts/benchmark-coding.js --resume `; existing job IDs are recovered, interrupted execution is not silently replayed, and an already recorded application is verified rather than applied again. Logical job failures remain scored failures. Use `--cases` with comma-separated task IDs for a smaller diagnostic run. The report has an explicit `complete` flag and unfinished IDs. The runner exits nonzero if any task is unaccepted or unfinished, but retains the report so failures remain part of the comparison. The profile summaries include: diff --git a/docs/worker-service.md b/docs/worker-service.md index cbcf3d8..239071a 100644 --- a/docs/worker-service.md +++ b/docs/worker-service.md @@ -54,7 +54,7 @@ The CLI accepts the same JSON as `npm run jobs -- submit tasks.json`, or a singl | `jobs_wait` | Wait up to 25 seconds for a terminal result, or a change after `after_revision`. | | `jobs_get` | Compact evidence; `detail: true` includes the contract, attempts, and acceptance output. | | `jobs_list` | Recover recent IDs; filter by status and paginate. | -| `jobs_read` | Read a character page from `patch` or `result`; continue at `next_offset`. | +| `jobs_read` | Read a character page from `patch`, `result`, or `trace`; continue at `next_offset`. | | `jobs_cancel` | Stop queued or active work while retaining evidence and workspaces. | | `jobs_apply` | Validate and apply a completed isolated patch to the original source. | | `jobs_status` | Inspect shared capacity, provider cooldowns, and counts. | @@ -103,6 +103,36 @@ Desktop sessions and legacy delegations keep their existing default agent. Permi Engine usage now reports `uncachedInTokens`, `cacheReadTokens`, `cacheWriteTokens`, `reasoningTokens`, and `modelRequests` alongside existing totals. `inTokens` includes uncached input plus cache reads/writes; `outTokens` includes output plus reasoning. Repeated usage events are deduplicated by message, and repair turns accumulate usage. These measure the observed session; independently running engine background/child sessions are not a complete account billing ledger. Missing detailed fields mean unavailable, not zero. +## Request traces and verification reserves + +Durable jobs save a bounded `trace.json`, retrievable with `jobs_read(id, artifact: "trace")`. Compact status includes the trace summary and queue/preparation/execution/collection timings. Benchmark runs preserve traces in a companion `.traces/` directory before deleting temporary workspaces. + +The trace merges engine assistant-message updates by ID and records observed per-request usage, timestamps, tool names, tool durations, output byte counts, and repeated read/search argument fingerprints. Fingerprints use a per-execution secret; saved traces contain no prompts, source text, tool arguments, tool outputs, or raw errors. Existing result/patch artifacts still contain their normal task evidence. Each request/tool table is capped at 1,000 entries, with discarded events counted. + +Timing is observational: assistant-message lifetimes can include tool execution; cumulative durations overlap and are not pure inference time. Missing timestamps remain unknown. Requests initialized with zero tokens are not marked usage-reported without a completed-step receipt or nonzero usage. Interrupted requests can therefore have unknown final usage. Native workers currently provide tool traces only, with request coverage marked unavailable; engine background/child work and internal provider retries are not fully captured. Traces become durable when execution returns, not after every event. Repeated argument fingerprints identify candidates for inspection, not proof that a read was unnecessary after edits. + +To reserve room for verification on an isolated, pinned OpenCode worker: + +```json +{ + "model": "opencode/big-pickle", + "engine_profile": "scoped", + "max_tokens": 200000, + "timeout_ms": 180000, + "verification_reserve_tokens": 40000, + "verification_reserve_ms": 30000, + "checks": ["npm test"] +} +``` + +Restart an older worker service with `npm run jobs -- stop` before using these capabilities; the client refuses to reuse a daemon from the previous capability version. + +Both reserve settings default to zero. They require `scoped` or `focused`, worktree isolation, and caller acceptance checks. At the first soft threshold in the initial model turn, OmniWork requests an engine abort, waits for the prompt response, and requires an acknowledged stop plus idle status. Only then does it run the checks. Passing checks can finish the job without an additional model-authored summary. Failed checks can trigger the existing bounded repair in the same agent/workspace; repairs use the remaining original budget and receive no second soft checkpoint. + +The hard token cap, original deadline, caller cancellation, ownership checks, and integration checks still apply. A request can overshoot the soft and hard token thresholds. Stop-confirmation failure or a provider error cannot be converted into success. Engine startup, tool shutdown, and check duration may exhaust the reserved time; these settings do not guarantee completion. Arbitrary detached processes are outside this coordination guarantee. Use strong acceptance commands; a passing smoke test cannot establish requirements it does not test. + +Run `node scripts/probe-engine-checkpoint.js` to exercise the installed engine against synthetic local inference. It writes a fixture, stalls a subsequent model response, and asserts stop/idle before verification. This probe spends no real inference tokens and does not measure coding-quality gains. + ## Context and practical boundaries Workers receive a bounded task contract, selected file excerpts, and a cached repository orientation map of relevant paths and declarations. The map is capped at 4,000 characters; explicit file excerpts total at most 24,000 characters. Full content remains accessible through tools. Parent clients receive compact evidence and can retrieve artifacts without absorbing every worker transcript. @@ -113,7 +143,7 @@ Worktrees isolate ordinary edits; they are not operating-system sandboxes. Worke There is no dependency graph, automatic cross-job conflict resolution, durable provider conversation resumption after a daemon crash, or automatic workspace garbage collection yet. Parallel tasks should have independent ownership. Retained worktrees and artifacts use disk space. On restart, uncertain in-flight execution is marked interrupted instead of silently replayed; inspect it before resubmission. An interrupted integration may require inspecting both source and the retained integration directory. The service exits after 15 idle minutes without queued or active jobs, and the next client restarts it. Completed results remain on disk. -Artifacts live beneath `/jobs/tasks//`; `job.json`, `result.json`, `changes.patch`, and the worktree provide evidence. The service descriptor contains a private token for its loopback API; do not share it. `service.log` records service errors. To clean a retained Git worktree, stop relevant jobs, inspect the output, and use `git worktree remove ` before deleting its artifact directory. +Artifacts live beneath `/jobs/tasks//`; `job.json`, `result.json`, `trace.json`, `changes.patch`, and the worktree provide evidence. The service descriptor contains a private token for its loopback API; do not share it. `service.log` records service errors. To clean a retained Git worktree, stop relevant jobs, inspect the output, and use `git worktree remove ` before deleting its artifact directory. ## Validation and design references diff --git a/electron/execution-trace.js b/electron/execution-trace.js new file mode 100644 index 0000000..dce7f05 --- /dev/null +++ b/electron/execution-trace.js @@ -0,0 +1,72 @@ +"use strict"; +const crypto = require("node:crypto"); +const number = v => Number.isFinite(v) && v >= 0 ? v : null; +const elapsed = row => row.startedAt != null && row.completedAt != null ? Math.max(0, row.completedAt - row.startedAt) : null; +const USAGE = ["input", "output", "reasoning"]; +// Canonicalize arguments only in memory. A per-execution secret prevents saved +// fingerprints from becoming a dictionary of repository paths or shell commands. +function canonical(value) { + if (Array.isArray(value)) return value.map(canonical); + if (value && typeof value === "object") return Object.fromEntries(Object.keys(value).sort().map(k => [k, canonical(value[k])])); + return value; +} +class ExecutionTrace { + constructor({ limit = 1000 } = {}) { + this.limit = limit; this.key = crypto.randomBytes(32); this.requests = new Map(); this.tools = new Map(); + this.discardedEvents = 0; this.verificationMs = 0; this.startedAt = Date.now(); + } + row(map, key, prefix) { + if (!key) return null; + if (map.has(key)) return map.get(key); + if (map.size >= this.limit) { this.discardedEvents++; return null; } + const row = { id: prefix + (map.size + 1), startedAt: null, completedAt: null }; + map.set(key, row); return row; + } + event(type, p, turn) { + if (!p?.id) return; + if (type === "request") { + const row = this.row(this.requests, `${turn}:${p.id}`, "r"); if (!row) return; + row.turn = turn; + if (typeof p.model === "string") row.model = p.model.slice(0, 300); + for (const k of ["startedAt", "completedAt"]) if (number(p[k]) != null) row[k] = p[k]; + if (p.failed === true) row.failed = true; + if (p.tokens) { + row.usage = Object.fromEntries(USAGE.map(k => [k, number(p.tokens[k])])); + row.usage.cacheRead = number(p.tokens.cache?.read); + row.usage.cacheWrite = number(p.tokens.cache?.write); + // OpenCode initializes in-flight messages with zero tokens. Those are + // not a provider usage receipt, especially when generation is aborted. + row.usageReported = Boolean(row.usageReported || p.usageReported || Object.values(row.usage).some(n => n > 0)); + } + } + if (type === "tool_call") { + const row = this.row(this.tools, `${turn}:${p.id}`, "t"); if (!row) return; + row.turn = turn; row.name = String(p.name || "unknown").slice(0, 100); + row.startedAt ??= number(p.startedAt) ?? Date.now(); + row.request = p.requestId ? this.row(this.requests, `${turn}:${p.requestId}`, "r")?.id || null : null; + row.fingerprint = crypto.createHmac("sha256", this.key).update(JSON.stringify([row.name, canonical(p.args || {})])).digest("hex").slice(0, 24); + } + if (type === "tool_result") { + const row = this.row(this.tools, `${turn}:${p.id}`, "t"); if (!row) return; + row.completedAt = number(p.completedAt) ?? Date.now(); row.ok = typeof p.ok === "boolean" ? p.ok : null; + row.outputBytes = number(p.outputBytes) ?? Buffer.byteLength(String(p.result || "")); + if (Number.isInteger(p.exitCode)) row.exitCode = p.exitCode; + } + } + snapshot() { + const requests = [...this.requests.values()].map(r => ({ ...r, elapsedMs: elapsed(r) })); + const tools = [...this.tools.values()].map(r => ({ ...r, elapsedMs: elapsed(r) })); + const reads = new Set(); let repeatedReads = 0; + for (const t of tools) if (/^(read|read_file|glob|grep|list|list_dir)$/.test(t.name)) { + if (reads.has(t.fingerprint)) repeatedReads++; else reads.add(t.fingerprint); + } + return { version: 1, requestCoverage: requests.length ? "observed" : "unavailable", coverage: "Observed engine assistant messages and tool events; provider retries, child sessions and full request payloads are not captured.", + summary: { requestCoverage: requests.length ? "observed" : "unavailable", requests: requests.length, requestsWithUsage: requests.filter(r => r.usageReported && r.usage?.input != null && r.usage?.output != null).length, + tools: tools.length, repeatedReads, toolOutputBytes: tools.reduce((n,t) => n + (t.outputBytes || 0), 0), + requestsWithTiming: requests.filter(r => r.elapsedMs != null).length, toolsWithTiming: tools.filter(t => t.elapsedMs != null).length, + cumulativeAssistantMs: requests.some(r => r.elapsedMs != null) ? requests.reduce((n,r) => n + (r.elapsedMs || 0), 0) : null, + cumulativeToolMs: tools.some(t => t.elapsedMs != null) ? tools.reduce((n,t) => n + (t.elapsedMs || 0), 0) : null, + verificationMs: this.verificationMs, executionMs: Date.now() - this.startedAt, discardedEvents: this.discardedEvents }, requests, tools }; + } +} +module.exports = { ExecutionTrace }; diff --git a/electron/execution.js b/electron/execution.js index e8b0d43..e2bd0fb 100644 --- a/electron/execution.js +++ b/electron/execution.js @@ -14,16 +14,29 @@ async function mapLimit(items, limit, run) { } // Observed outcomes, not the model's description of what it intended to do. -async function executeTask({ task, createAgent, recover, checks = [], runCheck, repairAttempts = 0, maxTokens = Infinity, timeoutMs = 600_000, signal, progress = () => {} }) { +async function executeTask({ task, createAgent, recover, checks = [], runCheck, repairAttempts = 0, maxTokens = Infinity, timeoutMs = 600_000, signal, progress = () => {}, trace = false, verificationReserveTokens = 0, verificationReserveMs = 0 }) { const started = Date.now(); + const telemetry = trace ? new (require("./execution-trace").ExecutionTrace)() : null; const controller = new AbortController(); let agent, error = null, completed = false, timedOut = false, steps = 0, budgetReason = null; + let turn = 0, inModelTurn = false, checkpointPromise = null, completionSource = "model"; + const checkpoint = { requested: false, confirmed: false, trigger: null }; + const reserveEnabled = checks.length > 0 && Boolean(runCheck) && (verificationReserveTokens > 0 || verificationReserveMs > 0); + const requestCheckpoint = trigger => { + if (!reserveEnabled || turn !== 1 || checkpoint.requested || !inModelTurn || controller.signal.aborted || error) return; + if (agent?.isEngine && !agent.sessionID) return; + checkpoint.requested = true; checkpoint.trigger = trigger; + progress(++steps, "stopping engine for verification"); + checkpointPromise = Promise.resolve().then(() => agent.pauseForVerification()).then(ok => { checkpoint.confirmed = ok === true; return checkpoint.confirmed; }).catch(() => false); + }; const changes = [], calls = new Map(), attempts = [], verification = []; const checkHistory = []; const usage = { inTokens: 0, outTokens: 0, estimated: false, available: false }; let lastUsage = { inTokens: 0, outTokens: 0 }; const emit = (type, p) => { if (controller.signal.aborted) return; + telemetry?.event(type, p, turn); + if (verificationReserveMs > 0 && Date.now() - started >= timeoutMs - verificationReserveMs) requestCheckpoint("time"); if (type === "subagent" && (p.kind === "tool_call" || p.kind === "tool_result")) { emit(p.kind, { ...p.payload, id: `${p.subId}:${p.payload.id}` }); return; @@ -50,21 +63,34 @@ async function executeTask({ task, createAgent, recover, checks = [], runCheck, } usage.estimated ||= Boolean(p.estimated); if (usage.available && usage.inTokens + usage.outTokens >= maxTokens) { budgetReason = "Observed token budget reached"; cancel(); } + else if (verificationReserveTokens > 0 && usage.available && usage.inTokens + usage.outTokens >= maxTokens - verificationReserveTokens) requestCheckpoint("tokens"); } }; let unblock; const cancelled = new Promise((r) => { unblock = r; }); const cancel = () => { controller.abort(); agent?.abort(); unblock(); }; const timer = setTimeout(() => { timedOut = true; cancel(); }, timeoutMs); + const reserveTimer = reserveEnabled && verificationReserveMs > 0 ? setTimeout(() => requestCheckpoint("time"), Math.max(1, timeoutMs - verificationReserveMs)) : null; signal?.addEventListener("abort", cancel, { once: true }); if (signal?.aborted) cancel(); + const send = async prompt => { + turn++; inModelTurn = true; + try { await agent.send(prompt); } finally { inModelTurn = false; } + }; const work = async () => { if (controller.signal.aborted) return; agent = await createAgent(emit, controller.signal); if (controller.signal.aborted) { agent.abort(); return; } + if (reserveEnabled && typeof agent.pauseForVerification !== "function") throw new Error("This agent cannot confirm a safe verification checkpoint"); const attempt = { model: agent.model, error: null }; attempts.push(attempt); - await agent.send(task); + await send(task); + if (checkpointPromise) { + const confirmed = await checkpointPromise; + if (controller.signal.aborted) return; + if (!confirmed) { error ||= "Engine stop could not be confirmed; verification skipped"; completed = false; } + else if (!error) { completed = true; completionSource = "checkpoint"; } + } Object.assign(attempt, { model: agent.effectiveModel || agent.model, error }); // Recovery is safe only before any tools were attempted. Otherwise retrying // a task from scratch can duplicate side effects. @@ -74,7 +100,7 @@ async function executeTask({ task, createAgent, recover, checks = [], runCheck, agent = next; error = null; completed = false; lastUsage = { inTokens: 0, outTokens: 0 }; const retry = { model: agent.model, error: null }; attempts.push(retry); - await agent.send(task); + await send(task); Object.assign(retry, { model: agent.effectiveModel || agent.model, error }); } } @@ -83,7 +109,9 @@ async function executeTask({ task, createAgent, recover, checks = [], runCheck, verification.length = 0; for (const command of checks) { if (controller.signal.aborted) return; + const checkStarted = Date.now(); const result = await runCheck(command, controller.signal); + if (telemetry) telemetry.verificationMs += Date.now() - checkStarted; if (controller.signal.aborted) return; verification.push({ command, ok: result.ok, exitCode: result.exitCode, output: result.text.slice(-8000) }); } @@ -94,7 +122,8 @@ async function executeTask({ task, createAgent, recover, checks = [], runCheck, completed = false; lastUsage = { inTokens: 0, outTokens: 0 }; const repair = { model: agent.model, phase: "repair", error: null }; attempts.push(repair); const evidence = verification.filter(c => !c.ok).map(c => `${c.command}\n${c.output}`).join("\n\n").slice(-12000); - await agent.send(`Acceptance checks failed. Repair the implementation in this existing workspace; preserve the original task and ownership constraints. Do not weaken, delete or bypass tests.\n\n${evidence}`); + await send(`Acceptance checks failed. Repair the implementation in this existing workspace; preserve the original task and ownership constraints. Do not weaken, delete or bypass tests.\n\n${evidence}`); + completionSource = "model"; repair.error = error; if (error || !completed || controller.signal.aborted) break; } @@ -103,13 +132,15 @@ async function executeTask({ task, createAgent, recover, checks = [], runCheck, try { await Promise.race([work().catch(e => { error = e.message; }), cancelled]); } finally { - clearTimeout(timer); signal?.removeEventListener("abort", cancel); + clearTimeout(timer); clearTimeout(reserveTimer); signal?.removeEventListener("abort", cancel); } const stopped = budgetReason || (timedOut ? "Task deadline exceeded" : controller.signal.aborted ? "Cancelled by caller" : error || (!completed ? "Agent stopped without a completion event" : null)); if (stopped && attempts.length) attempts[attempts.length - 1].error ||= stopped; const status = controller.signal.aborted ? (timedOut || budgetReason ? "partial" : "cancelled") : stopped ? (changes.length ? "partial" : "failed") : "completed"; return { - status, reason: stopped, summary: agent?.lastText || "", changes, attempts, toolCalls: calls.size, checkHistory, + status, reason: stopped, summary: agent?.lastText || (status === "completed" && completionSource === "checkpoint" ? "Acceptance checks passed after a confirmed engine stop." : ""), changes, attempts, toolCalls: calls.size, checkHistory, + ...(reserveEnabled ? { completion: { source: completionSource, checkpoint: { ...checkpoint } } } : {}), + ...(telemetry ? { trace: telemetry.snapshot() } : {}), model: agent?.effectiveModel || agent?.model || null, verification: { status: verification.length ? (verification.every(c => c.ok) ? "passed" : "failed") : "unverified", checks: verification }, usage: usage.available ? usage : { inTokens: null, outTokens: null, estimated: true, available: false }, elapsedMs: Date.now() - started, }; diff --git a/electron/job-client.js b/electron/job-client.js index 806ad97..8c5a200 100644 --- a/electron/job-client.js +++ b/electron/job-client.js @@ -10,7 +10,8 @@ function dataDir() { return process.platform === "darwin" ? path.join(home, "Library", "Application Support", "omniwork") : process.platform === "win32" ? path.join(process.env.APPDATA || path.join(home, "AppData", "Roaming"), "omniwork") : path.join(process.env.XDG_CONFIG_HOME || path.join(home, ".config"), "omniwork"); } function configId() { - return crypto.createHash("sha256").update(JSON.stringify([process.env.OMNIWORK_BASE_URL || "", process.env.OMNIWORK_API_KEY || "", process.env.OMNIWORK_OPENCODE_BIN || "", process.env.OPENCODE_CONFIG_CONTENT || ""])).digest("hex"); + // Capability epoch: older daemons would silently ignore verification reserves. + return crypto.createHash("sha256").update(JSON.stringify([2, process.env.OMNIWORK_BASE_URL || "", process.env.OMNIWORK_API_KEY || "", process.env.OMNIWORK_OPENCODE_BIN || "", process.env.OPENCODE_CONFIG_CONTENT || ""])).digest("hex"); } function location() { return path.join(dataDir(), "jobs"); } function descriptor() { try { return JSON.parse(fs.readFileSync(path.join(location(), "service.json"), "utf8")); } catch { return null; } } diff --git a/electron/job-daemon.js b/electron/job-daemon.js index 4196190..e1be8fa 100755 --- a/electron/job-daemon.js +++ b/electron/job-daemon.js @@ -61,6 +61,8 @@ const service = new JobService({ }, runCheck: (command, cwd, signal) => executeToolResult("run_command", { command }, { workspace: cwd, signal }), run: async opts => executeTask({ task: opts.task, signal: opts.signal, timeoutMs: opts.timeoutMs, + trace: true, verificationReserveTokens: opts.verification_reserve_tokens || 0, + verificationReserveMs: opts.verification_reserve_ms || 0, checks: opts.checks, repairAttempts: opts.repair_attempts, maxTokens: opts.max_tokens, progress: opts.progress, createAgent: async emit => { const isEngine = headless.opencode.isEngineModel(opts.model); diff --git a/electron/job-service.js b/electron/job-service.js index a3002b2..17452ad 100644 --- a/electron/job-service.js +++ b/electron/job-service.js @@ -28,7 +28,14 @@ function normalize(input) { if (!["focused", "scoped", "standard"].includes(engine_profile)) throw new Error("engine_profile must be focused, scoped or standard"); const isolation = input.isolation || "worktree"; if (!["worktree", "shared"].includes(isolation)) throw new Error("isolation must be worktree or shared"); + const verification_reserve_tokens = integer(input.verification_reserve_tokens, 0, 0, 1000000); + const verification_reserve_ms = integer(input.verification_reserve_ms, 0, 0, 900000); + if (verification_reserve_tokens || verification_reserve_ms) { + if (!model?.startsWith("opencode/") || engine_profile === "standard" || isolation !== "worktree" || !input.checks?.length) throw new Error("Verification reserves require a pinned OpenCode model, scoped/focused profile, worktree isolation and acceptance checks"); + if (verification_reserve_tokens >= (input.max_tokens ?? 200000) || verification_reserve_ms >= (input.timeout_ms ?? 180000)) throw new Error("Verification reserves must be smaller than the original job budgets"); + } return { task: input.task, cwd: fs.realpathSync(input.cwd), model, policy, isolation, engine_profile, + ...(verification_reserve_tokens || verification_reserve_ms ? { verification_reserve_tokens, verification_reserve_ms } : {}), checks: strings(input.checks, 10), setup: strings(input.setup, 4), allowed_paths: strings(input.allowed_paths, 100, 1000).map(workspace.relativeFile), context_files: strings(input.context_files, 20, 1000).map(workspace.relativeFile), @@ -107,6 +114,8 @@ class JobService extends EventEmitter { createdAt: job.createdAt, updatedAt: job.updatedAt, reason: job.reason || job.result?.reason || null, progress: job.progress, verification: job.result?.verification?.status || "unverified", summary: job.result?.summary?.slice(0, 1600) || "", usage: job.result?.usage || null, + trace: job.trace?.summary || null, + timings: job.timings || null, files: job.artifact?.files || [], outsideScope: job.artifact?.outsideScope || [], workspace: job.workspace?.cwd || null, patch: job.artifact?.patch || null, appliedAt: job.appliedAt || null, integration: job.integration?.status || null }; } @@ -174,6 +183,7 @@ class JobService extends EventEmitter { job.deadlineAt ||= Date.now() + job.spec.timeout_ms; this.save(job); this.active.set(job.id, ctl); state.active++; const dir = path.join(this.dir, job.id), started = Date.now(); + job.timings = { queueMs: (job.timings?.queueMs || 0) + Math.max(0, started - Date.parse(job.queuedAt || job.createdAt)) }; const deadline = setTimeout(() => ctl.abort(new Error("Job deadline exceeded")), Math.max(1, job.deadlineAt - Date.now())); let lastProgress = 0; (async () => { @@ -186,6 +196,7 @@ class JobService extends EventEmitter { job.setupComplete = true; this.save(job); const prompt = await workspace.context(job.spec, job.workspace); ctl.signal.throwIfAborted(); job.status = "running"; this.save(job); + job.timings.preparationMs = Date.now() - started; const priorTokens = (job.providerHistory || []).reduce((n, attempt) => n + (attempt.usage?.inTokens || 0) + (attempt.usage?.outTokens || 0), 0); job.result = await this.run({ ...job.spec, task: prompt, cwd: job.workspace.cwd, sourceCwd: job.spec.cwd, model: model.id, signal: ctl.signal, max_tokens: Math.max(1, job.spec.max_tokens - priorTokens), @@ -200,6 +211,8 @@ class JobService extends EventEmitter { job.reason = e.message; } finally { clearTimeout(deadline); + job.timings.executionMs = job.result?.elapsedMs ?? null; + const collectionStarted = Date.now(); let outcome = job.status; job.status = "collecting"; this.save(job); if (job.workspace) { @@ -207,6 +220,11 @@ class JobService extends EventEmitter { catch (e) { job.reason = `Could not collect patch: ${e.message}`; if (outcome === "completed") outcome = "partial"; } } if (job.artifact?.outsideScope?.length) { outcome = "partial"; job.reason = "Worker edited files outside allowed_paths; patch requires review"; } + if (job.result?.trace) { + atomic(path.join(dir, "trace.json"), job.result.trace); + job.trace = { summary: job.result.trace.summary }; + delete job.result.trace; + } if (job.result) atomic(path.join(dir, "result.json"), job.result); job.status = this.stopping ? "interrupted" : ctl.signal.aborted && ctl.signal.reason?.message !== "Job deadline exceeded" ? "cancelled" : outcome; // Retry only native provider failures before ANY tool ran. Never replay @@ -221,8 +239,10 @@ class JobService extends EventEmitter { job.providerHistory ||= []; job.providerHistory.push({ model: model.id, reason: job.reason, usage: job.result.usage }); this.rateLimited(key, /429/.test(job.reason) ? 60000 : 5000); job.status = "queued"; job.reason = "Waiting for provider recovery before a safe retry"; + job.queuedAt = new Date().toISOString(); } if (TERMINAL.has(job.status)) job.finishedAt = new Date().toISOString(); + job.timings.collectionMs = Date.now() - collectionStarted; this.save(job); state.active--; state[job.status === "completed" ? "completed" : "failed"]++; state.latencyMs = state.latencyMs == null ? Date.now() - started : state.latencyMs * 0.8 + (Date.now() - started) * 0.2; @@ -260,8 +280,8 @@ class JobService extends EventEmitter { } async read({ id, artifact = "patch", offset = 0, limit = 12000 }) { const job = this.job(id); - if (!["patch", "result"].includes(artifact)) throw new Error("artifact must be patch or result"); - const file = artifact === "patch" ? job.artifact?.patch : job.result && path.join(this.dir, id, "result.json"); + if (!["patch", "result", "trace"].includes(artifact)) throw new Error("artifact must be patch, result or trace"); + const file = artifact === "patch" ? job.artifact?.patch : artifact === "trace" ? job.trace && path.join(this.dir, id, "trace.json") : job.result && path.join(this.dir, id, "result.json"); if (!file) throw new Error("Artifact is not available yet"); const text = await fs.promises.readFile(file, "utf8"); const start = integer(offset, 0, 0, text.length), count = integer(limit, 12000, 1, 24000); diff --git a/electron/job-tools.js b/electron/job-tools.js index 28b4b05..431ee89 100644 --- a/electron/job-tools.js +++ b/electron/job-tools.js @@ -16,6 +16,8 @@ const properties = { max_tokens: { type: "integer", minimum: 1000, maximum: 2000000, description: "Stop after observed input/output usage reaches this budget; an in-flight request can overshoot. Default 200000." }, max_steps: { type: "integer", minimum: 1, maximum: 80, description: "Native agent step limit per turn; default 24. Engine jobs use deadline/token controls." }, repair_attempts: { type: "integer", minimum: 0, maximum: 3, description: "Same-worker repairs after acceptance failure, default 1; within the original deadline and token budget." }, + verification_reserve_tokens: { type: "integer", minimum: 0, maximum: 1000000, description: "Opt-in: stop the initial engine turn this many observed tokens before the hard cap, confirm idle, then verify and optionally repair. Requires pinned OpenCode model, scoped/focused profile, isolated worktree and checks. Default 0; an in-flight request may overshoot." }, + verification_reserve_ms: { type: "integer", minimum: 0, maximum: 900000, description: "Opt-in time reserved within the original deadline for confirmed-stop verification and repair. Same restrictions as verification_reserve_tokens. Default 0; neither reserve raises the hard limits." }, }; const id = { type: "string", description: "Durable job ID returned by jobs_submit." }; const TOOLS = [ @@ -26,7 +28,7 @@ const TOOLS = [ { name: "jobs_wait", description: "Wait up to 25 seconds for the first terminal job, or for a revision change when after_revision is supplied. Returns compact results and a revision cursor. Waiting does not cancel jobs on client disconnect; use jobs_cancel explicitly. Prefer this to repeated polling.", inputSchema: { type: "object", properties: { ids: { ...strings, minItems: 1, maxItems: 100 }, after_revision: { type: "integer", minimum: 0 }, timeout_ms: { type: "integer", minimum: 0, maximum: 25000 } }, required: ["ids"] } }, { name: "jobs_get", description: "Inspect a durable job's status, evidence, usage, workspace and patch. Compact by default; detail=true includes the full task contract, attempts, acceptance output and repair history. Use jobs_read for large patch or result artifacts.", inputSchema: { type: "object", properties: { id, detail: { type: "boolean" } }, required: ["id"] } }, { name: "jobs_list", description: "Recover job IDs after reconnecting, or inspect the shared worker backlog. Lists recent jobs with compact status and evidence, supports status filtering and pagination, and does not start new model work.", inputSchema: { type: "object", properties: { status: { type: "string" }, offset: { type: "integer", minimum: 0 }, limit: { type: "integer", minimum: 1, maximum: 100 } } } }, - { name: "jobs_read", description: "Read a bounded character page from a job's patch or full execution result. Follow next_offset when more content is needed. This avoids copying every worker transcript into the parent agent's context.", inputSchema: { type: "object", properties: { id, artifact: { type: "string", enum: ["patch", "result"] }, offset: { type: "integer", minimum: 0 }, limit: { type: "integer", minimum: 1, maximum: 24000 } }, required: ["id"] } }, + { name: "jobs_read", description: "Read a bounded page from a job's patch, execution result or metadata-only request/tool trace. Follow next_offset when more content is needed.", inputSchema: { type: "object", properties: { id, artifact: { type: "string", enum: ["patch", "result", "trace"] }, offset: { type: "integer", minimum: 0 }, limit: { type: "integer", minimum: 1, maximum: 24000 } }, required: ["id"] } }, { name: "jobs_cancel", description: "Explicitly cancel a queued or active durable job. Active workers and their shell commands are signalled to stop. Isolated work and evidence are retained for inspection; already terminal jobs are unchanged.", inputSchema: { type: "object", properties: { id }, required: ["id"] } }, { name: "jobs_apply", description: "Apply a completed isolated job's verified patch to its original workspace. Requires passing checks and owned-path compliance. Rejects overlapping source edits, reruns checks against a fresh integration snapshot, and preserves the user's Git index and branch. This changes source files.", inputSchema: { type: "object", properties: { id }, required: ["id"] } }, { name: "jobs_status", description: "Inspect global worker capacity, provider concurrency, native-request pacing, cooldowns and completion counts. Use when jobs are queued or blocked; capacity limits are shared across clients of this service.", inputSchema: { type: "object", properties: {} } }, diff --git a/electron/opencode-engine.js b/electron/opencode-engine.js index 363481f..b51560a 100644 --- a/electron/opencode-engine.js +++ b/electron/opencode-engine.js @@ -364,6 +364,12 @@ class Engine { }); } async abort(sessionID, directory) { return await this.#req("POST", `/session/${sessionID}/abort`, { directory, timeoutMs: 5000 }).catch(() => false); } + async isIdle(sessionID, directory) { + const statuses = await this.#req("GET", "/session/status", { directory, timeoutMs: 5000 }); + if (!statuses || typeof statuses !== "object" || Array.isArray(statuses)) return false; + if (!Object.values(statuses).every(s => s && ["idle", "busy", "retry"].includes(s.type))) return false; + return !Object.hasOwn(statuses, sessionID) || statuses[sessionID]?.type === "idle"; + } async replyPermission(sessionID, permissionID, response, directory) { return await this.#req("POST", `/session/${sessionID}/permissions/${permissionID}`, { body: { response }, directory, timeoutMs: 5000 }); } @@ -431,6 +437,19 @@ class OpenCodeAgent { get isEngine() { return true; } setWorkspace(dir) { this.workspace = dir; this.sessionID = null; } abort() { this.aborted = true; this.abortCtl?.abort(); if (this.sessionID) this.engine.abort(this.sessionID, this.workspace); } + pauseForVerification() { + if (!this.sessionID || this.aborted) return Promise.resolve(false); + if (!this.pausePromise) { + this.pausing = true; + // Keep the prompt response alive: closing its HTTP transport alone does + // not establish that the engine and its tools have stopped. + this.pausePromise = (async () => { + if (await this.engine.abort(this.sessionID, this.workspace) !== true) return false; + return await this.engine.isIdle(this.sessionID, this.workspace); + })().catch(() => false); + } + return this.pausePromise; + } setModel(model) { this.model = model; this.contextTokens = this.engine.modelsCache.list.find(m => m.id === model)?.context || 200_000; } async compactNow() { return null; } async oneShot(prompt) { @@ -463,6 +482,7 @@ class OpenCodeAgent { async send(userText, images) { this.aborted = false; + this.pausing = false; this.pausePromise = null; this.lastText = ""; this.abortCtl = new AbortController(); this.turnStats = { startedAt: Date.now(), inTokens: 0, outTokens: 0, estimated: true }; @@ -480,8 +500,9 @@ class OpenCodeAgent { const held = new Map(); // partID -> delta text that arrived before the part's type const seen = new Map(); // callID -> "called" | "done" const usageByMessage = new Map(); - const recordUsage = (id, tokens) => { + const recordUsage = (id, tokens, usageReported = false) => { if (!id || !Number.isFinite(tokens?.input) || !Number.isFinite(tokens?.output)) return; + this.emit("request", { id, model: `${providerID}/${modelID}`, tokens, usageReported }); usageByMessage.set(id, tokens); let input = 0, output = 0, uncached = 0, cacheRead = 0, cacheWrite = 0, reasoning = 0; for (const t of usageByMessage.values()) { @@ -504,7 +525,10 @@ class OpenCodeAgent { const p = ev.properties || {}; switch (ev.type) { case "message.updated": - if (p.info?.role === "assistant") recordUsage(p.info.id, p.info.tokens); + if (p.info?.role === "assistant") { + this.emit("request", { id: p.info.id, model: `${p.info.providerID || providerID}/${p.info.modelID || modelID}`, startedAt: p.info.time?.created, completedAt: p.info.time?.completed, failed: Boolean(p.info.error) }); + recordUsage(p.info.id, p.info.tokens); + } break; // A delta only names its part; the part's type came (or comes) with a // message.part.updated. Reasoning streams on field "text" too, so a @@ -518,7 +542,7 @@ class OpenCodeAgent { } case "message.part.updated": { const part = p.part || {}; - if (part.type === "step-finish") recordUsage(part.messageID, part.tokens); + if (part.type === "step-finish") recordUsage(part.messageID, part.tokens, true); if (part.id && part.type && !partType.has(part.id)) { partType.set(part.id, part.type); if (held.has(part.id)) { flush(part.id, part.type, held.get(part.id)); held.delete(part.id); } @@ -531,11 +555,11 @@ class OpenCodeAgent { const hasInput = st.input && Object.keys(st.input).length > 0; if (!seen.has(id) && (hasInput || st.status === "completed" || st.status === "error")) { seen.set(id, "called"); - this.emit("tool_call", { id, name: part.tool, args: st.input || {} }); + this.emit("tool_call", { id, name: part.tool, args: st.input || {}, requestId: part.messageID, startedAt: st.time?.start }); } if (seen.get(id) === "called" && (st.status === "completed" || st.status === "error")) { seen.set(id, "done"); - this.emit("tool_result", { id, name: part.tool, ok: st.status === "completed", result: st.status === "error" ? `Error in ${part.tool}: ${st.error || "failed"}` : String(st.output ?? st.title ?? "") }); + this.emit("tool_result", { id, name: part.tool, ok: st.status === "completed", completedAt: st.time?.end, outputBytes: Buffer.byteLength(String(st.output ?? st.error ?? "")), result: st.status === "error" ? `Error in ${part.tool}: ${st.error || "failed"}` : String(st.output ?? st.title ?? "") }); } break; } @@ -549,9 +573,11 @@ class OpenCodeAgent { }, this.workspace); const res = await this.engine.prompt(sid, { directory: this.workspace, providerID, modelID, text, signal: this.abortCtl.signal, agent: this.engineProfile === "scoped" ? workerProfile.SCOPED_NAME : this.engineProfile === "focused" ? workerProfile.NAME : undefined }); + this.emit("request", { id: res?.info?.id, model: `${providerID}/${modelID}`, startedAt: res?.info?.time?.created, completedAt: res?.info?.time?.completed, failed: Boolean(res?.info?.error) }); recordUsage(res?.info?.id, res?.info?.tokens); if (this.aborted) { this.emit("aborted", this.#stats()); return; } const err = res && res.info && res.info.error; + if (this.pausing && (!err || err.name === "MessageAbortedError")) { this.emit("stats", this.#stats()); return; } if (err) { const msg = (err.data && err.data.message) || err.name || "OpenCode session error"; this.emit("error", { message: `OpenCode (${modelID}): ${msg}` }); diff --git a/scripts/benchmark-coding.js b/scripts/benchmark-coding.js index 8b17d3c..3926b93 100644 --- a/scripts/benchmark-coding.js +++ b/scripts/benchmark-coding.js @@ -127,7 +127,12 @@ async function evaluate(plan, detail) { fs.mkdirSync(output + ".patches", { recursive: true }); fs.copyFileSync(detail.artifact.patch, path.join(output + ".patches", `${plan.case}-r${plan.round}-${plan.profile}.patch`)); } + if (detail.trace) { + fs.mkdirSync(output + ".traces", { recursive: true }); + fs.copyFileSync(path.join(root, "data", "jobs", "tasks", plan.id, "trace.json"), path.join(output + ".traces", `${plan.case}-r${plan.round}-${plan.profile}.json`)); + } return { id: plan.id, case: plan.case, round: plan.round, profile: plan.profile, status: detail.status, + trace: detail.trace?.summary || null, timings: detail.timings || null, reason: detail.reason, result: detail.result, files: detail.artifact?.files, heldout: hidden, integration, accepted: Boolean(final.passed) }; } (async () => { diff --git a/scripts/probe-engine-checkpoint.js b/scripts/probe-engine-checkpoint.js new file mode 100644 index 0000000..7447da5 --- /dev/null +++ b/scripts/probe-engine-checkpoint.js @@ -0,0 +1,46 @@ +#!/usr/bin/env node +"use strict"; +// Real installed OpenCode, local synthetic inference: write a fixture, then +// stall the next response so a time reserve must stop it before verification. +const assert = require("node:assert/strict"), fs = require("node:fs"), os = require("node:os"), path = require("node:path"), http = require("node:http"); +const { Engine, OpenCodeAgent, version } = require("../electron/opencode-engine"); +const { executeTask } = require("../electron/execution"); +const root = fs.mkdtempSync(path.join(os.tmpdir(), "ow-checkpoint-")); +let engine, requests = 0, checkedIdle = false; +const server = http.createServer(async (req, res) => { + let raw = ""; for await (const c of req) raw += c; + const body = JSON.parse(raw); requests++; + res.writeHead(200, { "Content-Type": "text/event-stream" }); + const packet = { id: `fixture-${requests}`, object: "chat.completion.chunk", created: 1, model: "coder" }; + const send = (delta, finish_reason = null, usage) => res.write(`data: ${JSON.stringify({ ...packet, choices: [{ index: 0, delta, finish_reason }], ...(usage ? { usage } : {}) })}\n\n`); + if (body.messages.some(m => m.role === "tool")) { + send({ role: "assistant", content: "The file is written; continuing to inspect." }); + // The engine must cancel this stream; there is no model completion event. + return; + } + send({ role: "assistant", tool_calls: [{ index: 0, id: "write_fixture", type: "function", function: { name: "write", arguments: JSON.stringify({ filePath: path.join(root, "answer.txt"), content: "READY\n" }) } }] }); + send({}, "tool_calls", { prompt_tokens: 100, completion_tokens: 5, total_tokens: 105 }); + res.end("data: [DONE]\n\n"); +}); +(async () => { + await new Promise(r => server.listen(0, "127.0.0.1", r)); + process.env.OPENCODE_CONFIG_CONTENT = JSON.stringify({ enabled_providers: ["fixture"], small_model: "fixture/coder", provider: { fixture: { + npm: "@ai-sdk/openai-compatible", options: { baseURL: `http://127.0.0.1:${server.address().port}/v1`, apiKey: "fixture" }, + models: { coder: { name: "Local checkpoint fixture", limit: { context: 100000, output: 2048 }, tool_call: true } }, + } } }); + engine = new Engine(); await engine.start(); await engine.models(); + let agent; + const result = await executeTask({ task: "Write answer.txt containing READY followed by a newline.", trace: true, checks: ["fixture file equals READY"], + maxTokens: 10000, timeoutMs: 15000, verificationReserveMs: 10000, + createAgent: async emit => (agent = new OpenCodeAgent({ engine, workspace: root, model: "opencode/fixture/coder", engineProfile: "scoped", emit })), + runCheck: async () => { checkedIdle = await engine.isIdle(agent.sessionID, root); const ok = checkedIdle && fs.readFileSync(path.join(root, "answer.txt"), "utf8") === "READY\n"; return { ok, exitCode: ok ? 0 : 1, text: ok ? "verified" : "failed" }; }, + }); + assert.equal(result.status, "completed", JSON.stringify({ status: result.status, reason: result.reason, completion: result.completion })); + assert(result.completion.checkpoint.confirmed && checkedIdle); assert(requests >= 2); + assert.equal(result.verification.status, "passed"); assert(result.elapsedMs < 15000); + const report = { testedAt: new Date().toISOString(), engineVersion: version(), scope: "Real installed engine, synthetic local inference; verifies stop-before-check, not coding quality or token savings.", requests, checkedIdle, + status: result.status, completion: result.completion, usage: result.usage, elapsedMs: result.elapsedMs, trace: result.trace }; + const index = process.argv.indexOf("--output"); + if (index >= 0) { fs.mkdirSync(path.dirname(process.argv[index + 1]), { recursive: true }); fs.writeFileSync(process.argv[index + 1], JSON.stringify(report, null, 2) + "\n"); } + console.log(JSON.stringify(report, null, 2)); +})().catch(e => { console.error(e); process.exitCode = 1; }).finally(() => { engine?.stop(); server.closeAllConnections(); server.close(); fs.rmSync(root, { recursive: true, force: true }); }); diff --git a/scripts/test-regression.js b/scripts/test-regression.js index 244f363..7bada3c 100644 --- a/scripts/test-regression.js +++ b/scripts/test-regression.js @@ -1,7 +1,7 @@ "use strict"; const { spawnSync } = require("node:child_process"); const path = require("node:path"); -const suites = ["tuning", "compact", "fallback", "providers", "opencode", "acp", "mcp", "modes", "approvals", "persist", "sidecar", "reliability", "jobs", "jobs-daemon", "coding-benchmark"]; +const suites = ["tuning", "compact", "fallback", "providers", "opencode", "acp", "mcp", "modes", "approvals", "persist", "sidecar", "reliability", "jobs", "jobs-daemon", "coding-benchmark", "execution-trace"]; let failed = false; for (const suite of suites) { const run = spawnSync(process.execPath, [path.join(__dirname, "..", "test", suite + ".js")], { encoding: "utf8", timeout: 120_000, env: { ...process.env, OMNIWORK_NO_PREWARM: "1", OMNIWORK_MODEL: "", OMNIWORK_MODEL_FALLBACKS: "" } }); diff --git a/test/execution-trace.js b/test/execution-trace.js new file mode 100644 index 0000000..d85d348 --- /dev/null +++ b/test/execution-trace.js @@ -0,0 +1,84 @@ +"use strict"; +const assert = require("node:assert/strict"); +const { ExecutionTrace } = require("../electron/execution-trace"); +const { executeTask } = require("../electron/execution"); +const delay = ms => new Promise(r => setTimeout(r, ms)); +(async () => { + const trace = new ExecutionTrace(); + trace.event("request", { id: "m", startedAt: 100, model: "provider/model" }, 1); + const tokens = { input: 20, output: 5, reasoning: 2, cache: { read: 40, write: 0 } }; + for (let i = 0; i < 3; i++) trace.event("request", { id: "m", completedAt: 150, tokens }, 1); + for (let i = 0; i < 2; i++) { + trace.event("tool_call", { id: "c" + i, name: "read", requestId: "m", args: { filePath: "/private/SECRET", offset: 1 }, startedAt: 151 }, 1); + trace.event("tool_result", { id: "c" + i, ok: true, result: "PRIVATE_CONTENT", outputBytes: 200, completedAt: 160 }, 1); + } + const t = trace.snapshot(); + assert.equal(t.requests.length, 1); assert.equal(t.requests[0].usage.input, 20); + assert.equal(t.requests[0].usage.cacheRead, 40); assert.equal(t.summary.repeatedReads, 1); + assert.equal(t.summary.toolOutputBytes, 400); assert.equal(t.summary.cumulativeAssistantMs, 50); + assert.equal(t.tools[0].request, t.requests[0].id); + assert(!/SECRET|PRIVATE_CONTENT|filePath/.test(JSON.stringify(t))); + const other = new ExecutionTrace(); + other.event("tool_call", { id: "x", name: "read", args: { offset: 1, filePath: "/private/SECRET" } }, 1); + assert.notEqual(other.snapshot().tools[0].fingerprint, t.tools[0].fingerprint); + trace.event("request", { id: "m", tokens }, 2); + assert.equal(trace.snapshot().requests.length, 2); + const bounded = new ExecutionTrace({ limit: 1 }); + bounded.event("request", {}, 1); bounded.event("request", { id: "a" }, 1); bounded.event("request", { id: "b" }, 1); + assert.equal(bounded.snapshot().requests.length, 1); assert.equal(bounded.snapshot().summary.discardedEvents, 1); + assert.equal(bounded.snapshot().summary.cumulativeAssistantMs, null); + bounded.event("request", { id: "a", failed: true, tokens: { input: 0, output: 0 } }, 1); + assert.equal(bounded.snapshot().summary.requestsWithUsage, 0, "initialized zero usage must not look like free inference"); + console.log("✓ traces merge request updates, retain unknown timing, bound growth and omit sensitive content"); + + async function scenario({ stopConfirmed = true, providerError = false, hardOvershoot = false, failCheck = false, cancelDuringStop = false, reserve = true } = {}) { + let sends = 0, checks = 0, active = false, stopped = false, event; + const ctl = new AbortController(); + const result = await executeTask({ task: "fix", trace: true, checks: ["verify"], repairAttempts: 1, + maxTokens: 1000, timeoutMs: 2000, verificationReserveTokens: reserve ? 300 : 0, signal: ctl.signal, + createAgent: async emit => { + event = emit; + return { model: "fixture", lastText: "", abort() { active = false; }, + async pauseForVerification() { + if (cancelDuringStop) ctl.abort(); + await delay(10); stopped = true; active = false; return stopConfirmed; + }, + async send() { + sends++; active = true; + emit("request", { id: "request", tokens: { input: sends === 1 ? 700 : 20, output: 1 } }); + emit("stats", { inTokens: hardOvershoot ? 1001 : sends === 1 ? 700 : 20, outTokens: 1 }); + if (providerError) emit("error", { message: "upstream rejected request" }); + await delay(20); active = false; + if (!reserve || sends > 1) emit("done", { inTokens: sends === 1 ? 700 : 20, outTokens: 1 }); + }, + }; + }, + runCheck: async () => { checks++; assert(!active, "verification raced a writer"); if (reserve) assert(stopped); return { ok: !failCheck || sends === 2, exitCode: failCheck && sends === 1 ? 1 : 0, text: "check evidence" }; }, + }); + // Late events from stopped work cannot turn cancellation into acceptance. + if (cancelDuringStop || hardOvershoot) event("done", { inTokens: 0, outTokens: 0 }); + return { result, sends, checks }; + } + let x = await scenario(); assert.equal(x.result.status, "completed"); assert.equal(x.result.completion.source, "checkpoint"); assert.equal(x.sends, 1); + x = await scenario({ stopConfirmed: false }); assert.notEqual(x.result.status, "completed"); assert.equal(x.checks, 0); + x = await scenario({ providerError: true }); assert.notEqual(x.result.status, "completed"); assert.equal(x.checks, 0); assert.match(x.result.reason, /upstream/); + x = await scenario({ hardOvershoot: true }); assert.equal(x.result.status, "partial"); assert.equal(x.checks, 0); + x = await scenario({ cancelDuringStop: true }); assert.equal(x.result.status, "cancelled"); assert.equal(x.checks, 0); + x = await scenario({ failCheck: true }); assert.equal(x.result.status, "completed"); assert.equal(x.sends, 2); assert.equal(x.result.usage.inTokens, 720); assert.equal(x.result.checkHistory.length, 1); assert.equal(x.result.trace.requests.length, 2); + x = await scenario({ reserve: false }); assert.equal(x.result.status, "completed"); assert.equal(x.result.completion, undefined); + let repairTurns = 0, repairPauses = 0; + const normalRepair = await executeTask({ task: "fix", maxTokens: 1000, verificationReserveTokens: 300, checks: ["verify"], repairAttempts: 1, + createAgent: async emit => ({ abort() {}, async pauseForVerification() { repairPauses++; return true; }, async send() { + repairTurns++; const usage = { inTokens: repairTurns === 1 ? 100 : 750, outTokens: 0 }; emit("stats", usage); emit("done", usage); + } }), + runCheck: async () => ({ ok: repairTurns === 2, exitCode: repairTurns === 2 ? 0 : 1, text: "repair required" }), + }); + assert.equal(normalRepair.status, "completed"); assert.equal(repairPauses, 0, "reserves may only interrupt the initial turn"); + let checks = 0; + const timeout = await executeTask({ task: "fix", maxTokens: 1000, timeoutMs: 50, verificationReserveTokens: 300, checks: ["test"], + createAgent: async emit => ({ abort() {}, pauseForVerification: async () => true, async send() { emit("stats", { inTokens: 750, outTokens: 0 }); } }), + runCheck: async () => { checks++; await delay(100); return { ok: true, exitCode: 0, text: "late" }; }, + }); + assert.equal(checks, 1); assert.equal(timeout.status, "partial"); assert.match(timeout.reason, /deadline/); + console.log("✓ checkpoints require confirmed stop, preserve errors/cancellation/hard budgets, and repair in the same agent"); +})().catch(e => { console.error(e); process.exitCode = 1; }); diff --git a/test/fixtures/fake-opencode.js b/test/fixtures/fake-opencode.js index 2c7630e..e5afac5 100755 --- a/test/fixtures/fake-opencode.js +++ b/test/fixtures/fake-opencode.js @@ -47,6 +47,7 @@ const server = http.createServer(async (req, res) => { const dir = req.headers["x-opencode-directory"] ? decodeURIComponent(req.headers["x-opencode-directory"]) : null; if (u.pathname === "/global/health") return json(res, 200, { healthy: true, version: "0.0.0-test" }); if (u.pathname === "/provider") return json(res, 200, PROVIDERS); + if (u.pathname === "/session/status") return json(res, 200, Object.fromEntries([...sessions].filter(([,s]) => s.busy || s.forceBusy).map(([id]) => [id, { type: "busy" }]))); if (u.pathname === "/event") { res.writeHead(200, { "Content-Type": "text/event-stream", "Cache-Control": "no-cache", Connection: "keep-alive" }); res.write(":ok\n\n"); clients.add(res); req.on("close", () => clients.delete(res)); return; @@ -59,7 +60,7 @@ const server = http.createServer(async (req, res) => { const m = /^\/session\/([^/]+)\/(message|abort|permissions\/([^/]+)|diff)$/.exec(u.pathname); if (m) { const s = sessions.get(m[1]); if (!s) return json(res, 404, { error: { type: "NotFound", message: "no session" } }); - if (m[2] === "abort") { s.aborted = true; return json(res, 200, true); } + if (m[2] === "abort") { s.aborted = true; while (s.busy) await sleep(5); return json(res, 200, true); } if (m[2] === "diff") return json(res, 200, []); if (m[2].startsWith("permissions/")) { const b = await read(req); const r = pending.get(m[3]); if (r) { r(b.response); pending.delete(m[3]); } return json(res, 200, true); } // message @@ -69,13 +70,16 @@ const server = http.createServer(async (req, res) => { if (!configured || configured.steps !== 24 || configured.permission?.skill === "allow" || configured.permission?.["*"] !== "deny" || !s.permission.some(p=>p.permission === "*" && p.action === "deny")) return json(res, 400, { error: { message: "Worker profile missing or unbounded" } }); } const text = (b.parts || []).map((p) => p.text || "").join("\n"); + s.forceBusy = text.includes("BUSY_AFTER_ABORT"); const messageID = nid("msg_"); + const created = Date.now(); s.busy = true; s.aborted = false; const partID = nid("prt_"); if (/PERMISSION/.test(text)) { const pid = nid("per_"); const response = await new Promise((resolve) => { pending.set(pid, resolve); send({ type: "permission.asked", properties: { id: pid, sessionID: s.id, permission: "bash", patterns: ["rm -rf build"], metadata: { command: "rm -rf build" }, always: [], tool: { messageID, callID: "call_perm" } } }); }); if (response === "reject") { + s.busy = false; return json(res, 200, { info: { id: messageID, sessionID: s.id, role: "assistant", time: { created: Date.now(), completed: Date.now() }, modelID: b.model.modelID, providerID: b.model.providerID }, parts: [{ id: partID, sessionID: s.id, messageID, type: "text", text: "permission was rejected" }] }); } } @@ -89,8 +93,9 @@ const server = http.createServer(async (req, res) => { await sleep(30); send({ type: "message.part.updated", properties: { sessionID: s.id, time: Date.now(), part: { id: nid("prt_"), sessionID: s.id, messageID, type: "tool", callID, tool: "bash", state: { status: "completed", input: { command: "echo hi" }, output: "hi\n", title: "echo hi", metadata: {}, time: { start: Date.now(), end: Date.now() } } } } }); } - if (/SLOW/.test(text)) { for (let i = 0; i < 20 && !s.aborted; i++) await sleep(100); if (s.aborted) return json(res, 200, { info: { id: messageID, sessionID: s.id, role: "assistant", time: { created: Date.now() }, error: { name: "MessageAbortedError", data: { message: "aborted" } } }, parts: [] }); } + if (/SLOW/.test(text)) { for (let i = 0; i < 20 && !s.aborted; i++) await sleep(100); if (s.aborted) { s.busy = false; return json(res, 200, { info: { id: messageID, sessionID: s.id, role: "assistant", time: { created }, error: { name: "MessageAbortedError", data: { message: "aborted" } } }, parts: [] }); } } if (/FAIL/.test(text)) { + s.busy = false; send({ type: "session.error", properties: { sessionID: s.id, error: { name: "APIError", data: { message: "upstream exploded" } } } }); return json(res, 200, { info: { id: messageID, sessionID: s.id, role: "assistant", time: { created: Date.now() }, error: { name: "APIError", data: { message: "upstream exploded" } } }, parts: [] }); } @@ -105,9 +110,10 @@ const server = http.createServer(async (req, res) => { await sleep(5); send({ type: "message.part.delta", properties: { sessionID: s.id, messageID, partID, field: "text", delta: answer.slice(5) } }); send({ type: "session.idle", properties: { sessionID: s.id } }); + s.busy = false; const tokens = { input: 50, output: 5, reasoning: 0, cache: { read: 0, write: 0 } }; send({ type: "message.part.updated", properties: { part: { id: nid("prt_"), sessionID: s.id, messageID, type: "step-finish", tokens } } }); - return json(res, 200, { info: { id: messageID, sessionID: s.id, role: "assistant", tokens, time: { created: Date.now(), completed: Date.now() }, modelID: b.model.modelID, providerID: b.model.providerID }, parts: [{ id: partID, sessionID: s.id, messageID, type: "text", text: answer }] }); + return json(res, 200, { info: { id: messageID, sessionID: s.id, role: "assistant", tokens, time: { created, completed: Date.now() }, modelID: b.model.modelID, providerID: b.model.providerID }, parts: [{ id: partID, sessionID: s.id, messageID, type: "text", text: answer }] }); } json(res, 404, { error: { type: "NotFound", message: u.pathname } }); }); diff --git a/test/jobs-daemon.js b/test/jobs-daemon.js index beb74e6..17ba25c 100644 --- a/test/jobs-daemon.js +++ b/test/jobs-daemon.js @@ -58,6 +58,8 @@ function rpcClient() { const repeated = await b.call("jobs_submit", make("client-one", [1,2])); check("reconnecting clients can retry a submission without duplicated execution", () => assert.deepEqual(repeated.jobs.map(j=>j.id),one.jobs.map(j=>j.id))); const read = await b.call("jobs_read", { id: ids[0], artifact: "patch" }); + const trace = JSON.parse((await b.call("jobs_read", { id: ids[0], artifact: "trace" })).text); + check("durable traces survive client exit and omit tool arguments and output", () => { assert.equal(trace.summary.tools, 1); assert(!JSON.stringify(trace).includes("READY")); assert(!JSON.stringify(trace).includes("file1.txt")); }); check("MCP returns isolated artifacts while source remains unchanged", () => { assert(read.text.includes("file1.txt")); assert(!fs.existsSync(path.join(repo,"file1.txt"))); }); const applied = await b.call("jobs_apply", { id: ids[0] }); check("MCP verified application reaches the original working directory", () => { assert(applied.applied); assert.equal(fs.readFileSync(path.join(repo,"file1.txt"),"utf8"),"READY"); }); diff --git a/test/jobs.js b/test/jobs.js index bfedfea..85182d6 100644 --- a/test/jobs.js +++ b/test/jobs.js @@ -50,6 +50,13 @@ const model = { id: "local/coder", provider: "local", free: true, tools: true }; assert.equal(normalize({ ...spec(1), engine_profile }).engine_profile, engine_profile); } assert.throws(() => normalize({ ...spec(1), engine_profile: "unknown" }), /engine_profile/); + assert.throws(() => normalize({ ...spec(1), verification_reserve_tokens: 100 }), /reserves require/); + const reserved = { ...spec(1), model: "opencode/big-pickle", engine_profile: "scoped", verification_reserve_tokens: 100 }; + assert.equal(normalize(reserved).verification_reserve_tokens, 100); + assert.throws(() => normalize({ ...reserved, checks: [] }), /reserves require/); + assert.throws(() => normalize({ ...reserved, isolation: "shared" }), /reserves require/); + assert.throws(() => normalize({ ...reserved, verification_reserve_ms: 180000 }), /smaller/); + assert.throws(() => normalize({ ...reserved, verification_reserve_tokens: 200000 }), /smaller/); }); const save = service.save; service.save = () => { throw new Error("fixture disk full"); }; diff --git a/test/opencode.js b/test/opencode.js index c8db7f8..b23a90f 100644 --- a/test/opencode.js +++ b/test/opencode.js @@ -70,6 +70,26 @@ function rpcClient(file, env) { check("engine usage includes intermediate steps and cached tokens without double counting", usage.inTokens === 170 && usage.outTokens === 17 && usage.estimated === false); check("engine usage separates uncached input, cache reads, reasoning and request count", usage.uncachedInTokens === 150 && usage.cacheReadTokens === 20 && usage.cacheWriteTokens === 0 && usage.reasoningTokens === 2 && usage.modelRequests === 2); + check("engine exposes per-message usage and tool correlation", tool.events.some(e => e.type === "request" && e.tokens?.input === 100) && call.requestId && result.outputBytes === 3); + const { executeTask } = require("../electron/execution"); + let checkpointAgent, checksAtIdle = 0; + const checkpointResult = await executeTask({ task: "TOOL SLOW", checks: ["fixture"], maxTokens: 1000, timeoutMs: 5000, verificationReserveTokens: 900, trace: true, + createAgent: async emit => (checkpointAgent = new opencode.OpenCodeAgent({ engine, workspace, engineProfile: "scoped", emit })), + runCheck: async () => { if (await engine.isIdle(checkpointAgent.sessionID, workspace)) checksAtIdle++; return { ok: true, exitCode: 0, text: "verified" }; }, + }); + check("engine checkpoint waits for abort acknowledgement and idle before checking", checkpointResult.status === "completed" && checkpointResult.completion?.checkpoint.confirmed && checksAtIdle === 1); + check("engine checkpoint retains request/tool trace", checkpointResult.trace.requests.length >= 1 && checkpointResult.trace.tools.length === 1); + const timedCheckpoint = await executeTask({ task: "SLOW", checks: ["fixture"], timeoutMs: 1500, verificationReserveMs: 1200, + createAgent: async emit => new opencode.OpenCodeAgent({ engine, workspace, engineProfile: "scoped", emit }), + runCheck: async () => ({ ok: true, exitCode: 0, text: "verified" }), + }); + check("time reserve interrupts inference within the original deadline", timedCheckpoint.status === "completed" && timedCheckpoint.completion?.checkpoint.trigger === "time" && timedCheckpoint.elapsedMs < 1500); + let prematureChecks = 0; + const stillBusy = await executeTask({ task: "TOOL SLOW BUSY_AFTER_ABORT", checks: ["fixture"], maxTokens: 1000, timeoutMs: 5000, verificationReserveTokens: 900, + createAgent: async emit => new opencode.OpenCodeAgent({ engine, workspace, engineProfile: "scoped", emit }), + runCheck: async () => { prematureChecks++; return { ok: true, exitCode: 0, text: "must not run" }; }, + }); + check("an abort acknowledgement alone cannot authorize verification while status is busy", stillBusy.status !== "completed" && prematureChecks === 0 && /not be confirmed/.test(stillBusy.reason)); const prompt = engine.prompt.bind(engine); let selectedAgent; engine.prompt = (sid, opts) => { selectedAgent = opts.agent; return prompt(sid, opts); }; const focused = await run("TOOL then say READY", { engineProfile: "focused" });