diff --git a/.changeset/guard-telemetry.md b/.changeset/guard-telemetry.md new file mode 100644 index 000000000000..ee4177237518 --- /dev/null +++ b/.changeset/guard-telemetry.md @@ -0,0 +1,9 @@ +--- +"@reddb-io/redcode": minor +"@reddb-io/redcode-core": minor +"@reddb-io/redcode-schema": minor +--- + +Write down every time a guard intervenes, so the thresholds can be argued from evidence + +Five guards ship in 0.14.0 — the inactivity watchdog, tool deadlines, the loop guard, the step budget, the bounds on naming and compacting — and every threshold in them was chosen by argument, because there was nothing to measure. Each intervention is now recorded with which guard fired, what it acted on, and what it did, and published as a live `session.next.guard.tripped` event. `redcode debug guards` reads it back: counts per guard and action over the last week, loudest first, plus the most recent trips. An empty report says so in words, because "nothing fired" and "nothing was collected" are different answers. diff --git a/packages/app/src/pages/session/timeline/observe-element-offset.test.ts b/packages/app/src/pages/session/timeline/observe-element-offset.test.ts index 1e972a3c85d1..a576dca45f49 100644 --- a/packages/app/src/pages/session/timeline/observe-element-offset.test.ts +++ b/packages/app/src/pages/session/timeline/observe-element-offset.test.ts @@ -46,13 +46,16 @@ test("reports a divergent native offset once and ignores equal offsets and unrel route.remove() document.body.append(route) await new Promise((resolve) => setTimeout(resolve, 0)) - await frames(3) + // Waited for rather than counted in frames: three frames is plenty on a quiet machine and not + // enough on a loaded CI runner, and the difference has nothing to do with what is being tested. + await until(() => calls.length > 0) expect(calls).toEqual([[0, false]]) route.remove() document.body.append(route) await new Promise((resolve) => setTimeout(resolve, 0)) await frames(3) + // Still one call: the offset now matches, so there is nothing new to report. expect(calls).toEqual([[0, false]]) cleanup?.() @@ -233,6 +236,17 @@ test("reconnects when the batch reports the addition before the removal", async } }) +/** Waits for a condition across animation frames, up to a generous deadline. */ +async function until(condition: () => boolean, budgetMs = 2_000) { + const deadline = Date.now() + budgetMs + while (!condition() && Date.now() < deadline) { + await frames(1) + // A macrotask between frames: the observer's callback is delivered on one, and a loop of + // nothing but animation frames can starve it. + await new Promise((resolve) => setTimeout(resolve, 1)) + } +} + async function frames(count: number) { for (let index = 0; index < count; index++) { await new Promise((resolve) => requestAnimationFrame(() => resolve())) diff --git a/packages/core/schema.json b/packages/core/schema.json index d0eeeebd5c41..20f07c856424 100644 --- a/packages/core/schema.json +++ b/packages/core/schema.json @@ -1,8 +1,8 @@ { "version": "7", "dialect": "sqlite", - "id": "f14a9b18-8207-487e-a3d3-227e629ba9ad", - "prevIds": ["169a0f0f-d58f-479f-b024-fa1c7b9a09db"], + "id": "36772f61-4ca4-48df-b27c-6aa39eb59ba1", + "prevIds": ["f14a9b18-8207-487e-a3d3-227e629ba9ad"], "ddl": [ { "name": "workspace", @@ -60,6 +60,10 @@ "name": "session_context_epoch", "entityType": "tables" }, + { + "name": "session_guard_trip", + "entityType": "tables" + }, { "name": "session_input", "entityType": "tables" @@ -920,6 +924,86 @@ "entityType": "columns", "table": "session_context_epoch" }, + { + "type": "text", + "notNull": false, + "autoincrement": false, + "default": null, + "generated": null, + "name": "id", + "entityType": "columns", + "table": "session_guard_trip" + }, + { + "type": "text", + "notNull": true, + "autoincrement": false, + "default": null, + "generated": null, + "name": "session_id", + "entityType": "columns", + "table": "session_guard_trip" + }, + { + "type": "text", + "notNull": true, + "autoincrement": false, + "default": null, + "generated": null, + "name": "guard", + "entityType": "columns", + "table": "session_guard_trip" + }, + { + "type": "text", + "notNull": true, + "autoincrement": false, + "default": null, + "generated": null, + "name": "action", + "entityType": "columns", + "table": "session_guard_trip" + }, + { + "type": "text", + "notNull": false, + "autoincrement": false, + "default": null, + "generated": null, + "name": "subject", + "entityType": "columns", + "table": "session_guard_trip" + }, + { + "type": "text", + "notNull": true, + "autoincrement": false, + "default": null, + "generated": null, + "name": "detail", + "entityType": "columns", + "table": "session_guard_trip" + }, + { + "type": "integer", + "notNull": true, + "autoincrement": false, + "default": null, + "generated": null, + "name": "time_created", + "entityType": "columns", + "table": "session_guard_trip" + }, + { + "type": "integer", + "notNull": true, + "autoincrement": false, + "default": null, + "generated": null, + "name": "time_updated", + "entityType": "columns", + "table": "session_guard_trip" + }, { "type": "text", "notNull": false, @@ -1728,6 +1812,13 @@ "table": "session_context_epoch", "entityType": "pks" }, + { + "columns": ["id"], + "nameExplicit": false, + "name": "session_guard_trip_pk", + "table": "session_guard_trip", + "entityType": "pks" + }, { "columns": ["id"], "nameExplicit": false, @@ -1872,6 +1963,34 @@ "entityType": "indexes", "table": "part" }, + { + "columns": [ + { + "value": "session_id", + "isExpression": false + } + ], + "isUnique": false, + "where": null, + "origin": "manual", + "name": "session_guard_trip_session_idx", + "entityType": "indexes", + "table": "session_guard_trip" + }, + { + "columns": [ + { + "value": "time_created", + "isExpression": false + } + ], + "isUnique": false, + "where": null, + "origin": "manual", + "name": "session_guard_trip_created_idx", + "entityType": "indexes", + "table": "session_guard_trip" + }, { "columns": [ { diff --git a/packages/core/src/database/migration.gen.ts b/packages/core/src/database/migration.gen.ts index e6ea4eaa1477..93f1b3322cc9 100644 --- a/packages/core/src/database/migration.gen.ts +++ b/packages/core/src/database/migration.gen.ts @@ -40,5 +40,6 @@ export const migrations = ( import("./migration/20260622142730_simplify_session_context_epoch"), import("./migration/20260622170816_reset_v2_session_state"), import("./migration/20260622202450_simplify_session_input"), + import("./migration/20260904202310_session_guard_trip"), ]) ).map((module) => module.default) satisfies DatabaseMigration.Migration[] diff --git a/packages/core/src/database/migration/20260904202310_session_guard_trip.ts b/packages/core/src/database/migration/20260904202310_session_guard_trip.ts new file mode 100644 index 000000000000..4274469b88ce --- /dev/null +++ b/packages/core/src/database/migration/20260904202310_session_guard_trip.ts @@ -0,0 +1,24 @@ +import { Effect } from "effect" +import type { DatabaseMigration } from "../migration" + +export default { + id: "20260904202310_session_guard_trip", + up(tx) { + return Effect.gen(function* () { + yield* tx.run(` + CREATE TABLE \`session_guard_trip\` ( + \`id\` text PRIMARY KEY, + \`session_id\` text NOT NULL, + \`guard\` text NOT NULL, + \`action\` text NOT NULL, + \`subject\` text, + \`detail\` text NOT NULL, + \`time_created\` integer NOT NULL, + \`time_updated\` integer NOT NULL + ); + `) + yield* tx.run(`CREATE INDEX \`session_guard_trip_session_idx\` ON \`session_guard_trip\` (\`session_id\`);`) + yield* tx.run(`CREATE INDEX \`session_guard_trip_created_idx\` ON \`session_guard_trip\` (\`time_created\`);`) + }) + }, +} satisfies DatabaseMigration.Migration diff --git a/packages/core/src/database/schema.gen.ts b/packages/core/src/database/schema.gen.ts index ed60fde6c55f..13ce11dc9c7f 100644 --- a/packages/core/src/database/schema.gen.ts +++ b/packages/core/src/database/schema.gen.ts @@ -154,6 +154,18 @@ export default { CONSTRAINT \`fk_session_context_epoch_session_id_session_id_fk\` FOREIGN KEY (\`session_id\`) REFERENCES \`session\`(\`id\`) ON DELETE CASCADE ); `) + yield* tx.run(` + CREATE TABLE \`session_guard_trip\` ( + \`id\` text PRIMARY KEY, + \`session_id\` text NOT NULL, + \`guard\` text NOT NULL, + \`action\` text NOT NULL, + \`subject\` text, + \`detail\` text NOT NULL, + \`time_created\` integer NOT NULL, + \`time_updated\` integer NOT NULL + ); + `) yield* tx.run(` CREATE TABLE \`session_input\` ( \`id\` text PRIMARY KEY, @@ -246,6 +258,8 @@ export default { ) yield* tx.run(`CREATE INDEX \`part_message_id_id_idx\` ON \`part\` (\`message_id\`,\`id\`);`) yield* tx.run(`CREATE INDEX \`part_session_idx\` ON \`part\` (\`session_id\`);`) + yield* tx.run(`CREATE INDEX \`session_guard_trip_session_idx\` ON \`session_guard_trip\` (\`session_id\`);`) + yield* tx.run(`CREATE INDEX \`session_guard_trip_created_idx\` ON \`session_guard_trip\` (\`time_created\`);`) yield* tx.run( `CREATE INDEX \`session_input_session_pending_delivery_seq_idx\` ON \`session_input\` (\`session_id\`,\`promoted_seq\`,\`delivery\`,\`admitted_seq\`);`, ) diff --git a/packages/core/src/session/message-updater.ts b/packages/core/src/session/message-updater.ts index 46118a89fe4b..9781aa2fd3cb 100644 --- a/packages/core/src/session/message-updater.ts +++ b/packages/core/src/session/message-updater.ts @@ -137,6 +137,9 @@ export function update(adapter: Adapter, event: SessionEvent.Event) { ) }, "session.next.prompt.admitted": () => Effect.void, + // Diagnostics about the run, not part of the conversation: counted elsewhere, nothing to + // project into a message here. + "session.next.guard.tripped": () => Effect.void, "session.next.context.updated": (event) => adapter.appendMessage( SessionMessage.System.make({ diff --git a/packages/core/src/session/sql.ts b/packages/core/src/session/sql.ts index 28c38ccabb5b..2397ea3574cc 100644 --- a/packages/core/src/session/sql.ts +++ b/packages/core/src/session/sql.ts @@ -137,6 +137,34 @@ export const SessionMessageTable = sqliteTable( ], ) +/** + * Every time one of the turn's guards intervened. + * + * Diagnostics, deliberately not a durable session event: this is how we find out whether the + * watchdog, the tool deadlines, the loop guard and the step budget ever fire in real use, and + * whether they fire when they should not. Thresholds were chosen by argument; this is what lets + * them be chosen by evidence. Deleting the table loses nothing but the record. + */ +export const SessionGuardTripTable = sqliteTable( + "session_guard_trip", + { + id: text().primaryKey(), + session_id: text().$type().notNull(), + /** stall | tool_timeout | loop | steps | aux */ + guard: text().notNull(), + /** warn | correct | stop */ + action: text().notNull(), + /** The tool, the phase, or whatever names the thing that tripped it. */ + subject: text(), + detail: text().notNull(), + ...Timestamps, + }, + (table) => [ + index("session_guard_trip_session_idx").on(table.session_id), + index("session_guard_trip_created_idx").on(table.time_created), + ], +) + export const SessionInputTable = sqliteTable( "session_input", { diff --git a/packages/redcode/src/cli/cmd/debug/guards.ts b/packages/redcode/src/cli/cmd/debug/guards.ts new file mode 100644 index 000000000000..349a9438a248 --- /dev/null +++ b/packages/redcode/src/cli/cmd/debug/guards.ts @@ -0,0 +1,48 @@ +import { Effect } from "effect" +import { SessionGuardLog } from "@/session/guard-log" +import { effectCmd } from "../../effect-cmd" + +const DAY_MS = 86_400_000 + +/** + * What the turn's guards actually did. + * + * Every threshold in them was argued into place — ten minutes for a tool, three identical calls + * for a loop, two steps of grace before the wall. This is the command that turns the next argument + * into a reading: how often each one fired, on what, and whether it was right. + */ +export const GuardsCommand = effectCmd({ + command: "guards", + describe: "how often the turn guards intervened, and on what", + builder: (yargs) => + yargs + .option("days", { type: "number", default: 7, description: "how far back to look" }) + .option("limit", { type: "number", default: 20, description: "how many recent trips to print" }), + handler: Effect.fn("Cli.debug.guards")(function* (args) { + const since = Date.now() - Math.max(0, args.days) * DAY_MS + const summary = yield* SessionGuardLog.Service.use((svc) => svc.summary({ since })) + const recent = yield* SessionGuardLog.Service.use((svc) => svc.recent({ since, limit: args.limit })) + + if (summary.length === 0) { + console.log(`No guard fired in the last ${args.days} day(s).`) + // Said plainly: an empty table reads as "no data collected", which is a different thing. + console.log("That means every turn finished on its own, or this build has not run since they landed.") + return + } + + console.log(`Guards that fired in the last ${args.days} day(s):\n`) + const width = Math.max(...summary.map((row) => row.guard.length)) + for (const row of summary) { + console.log(` ${row.guard.padEnd(width)} ${row.action.padEnd(7)} ${row.count}`) + } + + if (recent.length === 0) return + console.log(`\nMost recent:\n`) + for (const entry of recent) { + const when = new Date(entry.at).toISOString().replace("T", " ").slice(0, 19) + const subject = entry.subject ? ` ${entry.subject}` : "" + console.log(` ${when} ${entry.guard}/${entry.action}${subject}`) + console.log(` ${entry.detail.split("\n")[0]}`) + } + }), +}) diff --git a/packages/redcode/src/cli/cmd/debug/index.ts b/packages/redcode/src/cli/cmd/debug/index.ts index 2c3c1e18e24a..b509bbfe0e53 100644 --- a/packages/redcode/src/cli/cmd/debug/index.ts +++ b/packages/redcode/src/cli/cmd/debug/index.ts @@ -6,6 +6,7 @@ import { Duration, Effect } from "effect" import { effectCmd } from "../../effect-cmd" import { cmd } from "../cmd" import { ConfigCommand } from "./config" +import { GuardsCommand } from "./guards" import { FileCommand } from "./file" import { LSPCommand } from "./lsp" import { RipgrepCommand } from "./ripgrep" @@ -23,6 +24,7 @@ export const DebugCommand = cmd({ builder: (yargs) => yargs .command(ConfigCommand) + .command(GuardsCommand) .command(LSPCommand) .command(RipgrepCommand) .command(FileCommand) diff --git a/packages/redcode/src/effect/app-runtime.ts b/packages/redcode/src/effect/app-runtime.ts index 177cae146e1b..87f5eff74908 100644 --- a/packages/redcode/src/effect/app-runtime.ts +++ b/packages/redcode/src/effect/app-runtime.ts @@ -29,6 +29,7 @@ import { SessionCompaction } from "@/session/compaction" import { SessionRevert } from "@/session/revert" import { SessionSummary } from "@/session/summary" import { SessionPrompt } from "@/session/prompt" +import { SessionGuardLog } from "@/session/guard-log" import { Instruction } from "@/session/instruction" import { LLM } from "@/session/llm" import { LSP } from "@/lsp/lsp" @@ -88,6 +89,7 @@ export const AppLayer = AppNodeBuilderV1.build( SessionRevert.node, SessionSummary.node, SessionPrompt.node, + SessionGuardLog.node, Instruction.node, LLM.node, LSP.node, diff --git a/packages/redcode/src/session/compaction.ts b/packages/redcode/src/session/compaction.ts index b5a542cb8cd4..5d8f028ef3cf 100644 --- a/packages/redcode/src/session/compaction.ts +++ b/packages/redcode/src/session/compaction.ts @@ -8,6 +8,7 @@ import { MessageV2 } from "./message-v2" import { Token } from "@/util/token" import { SessionProcessor } from "./processor" import { AuxDeadline } from "./aux-deadline" +import { SessionGuardLog } from "./guard-log" import { Agent } from "@/agent/agent" import { SessionEvent } from "@reddb-io/redcode-core/session/event" import { Plugin } from "@/plugin" @@ -202,6 +203,7 @@ const layer = Layer.effect( Service, Effect.gen(function* () { const config = yield* Config.Service + const guards = yield* SessionGuardLog.Service const session = yield* Session.Service const agents = yield* Agent.Service const plugin = yield* Plugin.Service @@ -485,6 +487,13 @@ const layer = Layer.effect( duration: Duration.millis(compactionMs), orElse: () => Effect.gen(function* () { + yield* guards.record({ + sessionID: input.sessionID, + guard: "aux", + action: "stop", + subject: "compaction", + detail: AuxDeadline.message("compaction", compactionMs), + }) yield* Effect.logWarning(AuxDeadline.message("compaction", compactionMs), { "session.id": input.sessionID, }) @@ -648,6 +657,7 @@ export const node = LayerNode.make({ service: Service, layer: layer, deps: [ + SessionGuardLog.node, Config.node, Session.node, Agent.node, diff --git a/packages/redcode/src/session/guard-log.ts b/packages/redcode/src/session/guard-log.ts new file mode 100644 index 000000000000..c2050763aea2 --- /dev/null +++ b/packages/redcode/src/session/guard-log.ts @@ -0,0 +1,135 @@ +import { LayerNode } from "@reddb-io/redcode-core/effect/layer-node" +import { Database } from "@reddb-io/redcode-core/database/database" +import { SessionGuardTripTable } from "@reddb-io/redcode-core/session/sql" +import { SessionEvent } from "@reddb-io/redcode-core/session/event" +import { EventV2Bridge } from "@/event-v2-bridge" +import { Context, DateTime, Effect, Layer } from "effect" +import { desc, gte } from "drizzle-orm" +import { ulid } from "ulid" +import type { SessionID } from "./schema" + +/** + * The record of every time a guard intervened. + * + * We shipped five guards — the inactivity watchdog, tool deadlines, the loop guard, the step + * budget, the bounds on the calls around a turn — and every threshold in them was chosen by + * argument. Without a record of when they fire, and on what, the next threshold is another + * argument. This is what turns them into a measurement. + * + * Writing must never be able to break a turn: a guard that cannot be recorded still acts. + */ +export type Guard = "stall" | "tool_timeout" | "loop" | "steps" | "aux" +export type Action = "warn" | "correct" | "stop" + +export interface Trip { + readonly sessionID: SessionID + readonly guard: Guard + readonly action: Action + /** The tool, phase or call it acted on. */ + readonly subject?: string + readonly detail: string +} + +export interface Entry extends Trip { + readonly id: string + readonly at: number +} + +export interface Summary { + readonly guard: Guard + readonly action: Action + readonly count: number +} + +export interface Interface { + readonly record: (trip: Trip) => Effect.Effect + /** Most recent first. */ + readonly recent: (input?: { since?: number; limit?: number }) => Effect.Effect + readonly summary: (input?: { since?: number }) => Effect.Effect +} + +export class Service extends Context.Service()("@redcode/SessionGuardLog") {} + +export function summarize(entries: readonly Pick[]): Summary[] { + const counts = new Map() + for (const entry of entries) { + const key = `${entry.guard}:${entry.action}` + const found = counts.get(key) + if (found) counts.set(key, { ...found, count: found.count + 1 }) + else counts.set(key, { guard: entry.guard, action: entry.action, count: 1 }) + } + // Loudest first: what fires most is what most needs its threshold questioned. + return [...counts.values()].sort((a, b) => b.count - a.count || a.guard.localeCompare(b.guard)) +} + +const layer = Layer.effect( + Service, + Effect.gen(function* () { + const { db } = yield* Database.Service + const events = yield* EventV2Bridge.Service + + const record = Effect.fn("SessionGuardLog.record")(function* (trip: Trip) { + const at = Date.now() + yield* db + .insert(SessionGuardTripTable) + .values({ + id: ulid(), + session_id: trip.sessionID, + guard: trip.guard, + action: trip.action, + subject: trip.subject ?? null, + detail: trip.detail, + time_created: at, + time_updated: at, + }) + .run() + // Losing the record of an intervention is a worse outcome than the turn failing over it, + // but only just: the intervention itself has already happened either way. + .pipe(Effect.catchCause((cause) => Effect.logWarning("could not record a guard trip", { cause }))) + yield* events + .publish(SessionEvent.Guard.Tripped, { + timestamp: yield* DateTime.now, + sessionID: trip.sessionID, + guard: trip.guard, + action: trip.action, + ...(trip.subject ? { subject: trip.subject } : {}), + detail: trip.detail, + }) + .pipe(Effect.ignore) + }) + + const rows = (input?: { since?: number; limit?: number }) => + Effect.gen(function* () { + const base = db.select().from(SessionGuardTripTable) + const filtered = input?.since ? base.where(gte(SessionGuardTripTable.time_created, input.since)) : base + const ordered = filtered.orderBy(desc(SessionGuardTripTable.time_created)) + return yield* (input?.limit ? ordered.limit(input.limit) : ordered).all().pipe(Effect.orDie) + }) + + const recent = Effect.fn("SessionGuardLog.recent")(function* (input?: { since?: number; limit?: number }) { + const found = yield* rows(input) + return found.map( + (row): Entry => ({ + id: row.id, + sessionID: row.session_id, + guard: row.guard as Guard, + action: row.action as Action, + ...(row.subject ? { subject: row.subject } : {}), + detail: row.detail, + at: row.time_created, + }), + ) + }) + + const summary = Effect.fn("SessionGuardLog.summary")(function* (input?: { since?: number }) { + const found = yield* rows({ since: input?.since }) + return summarize(found.map((row) => ({ guard: row.guard as Guard, action: row.action as Action }))) + }) + + return Service.of({ record, recent, summary }) + }), +) + +export const node = LayerNode.make({ service: Service, layer, deps: [Database.node, EventV2Bridge.node] }) + +export * as SessionGuardLog from "./guard-log" diff --git a/packages/redcode/src/session/processor.ts b/packages/redcode/src/session/processor.ts index 4423be849f2a..ccf628855bdd 100644 --- a/packages/redcode/src/session/processor.ts +++ b/packages/redcode/src/session/processor.ts @@ -24,6 +24,7 @@ import { errorMessage } from "@/util/error" import { isRecord } from "@/util/record" import { EventV2Bridge } from "@/event-v2-bridge" import { LoopGuard } from "./loop-guard" +import { SessionGuardLog } from "./guard-log" import { SessionEvent } from "@reddb-io/redcode-core/session/event" import { Database } from "@reddb-io/redcode-core/database/database" import { Usage, type LLMEvent } from "@reddb-io/redcode-llm" @@ -114,6 +115,7 @@ const layer = Layer.effect( const agents = yield* Agent.Service const llm = yield* LLM.Service const permission = yield* Permission.Service + const guards = yield* SessionGuardLog.Service const plugin = yield* Plugin.Service const summary = yield* SessionSummary.Service const scope = yield* Scope.Scope @@ -744,6 +746,13 @@ const layer = Layer.effect( const parts = turn.flatMap((item) => item.parts) const decision = LoopGuard.assess({ parts, next: input, limits: bounds }) if (decision.type === "ok") return decision + yield* guards.record({ + sessionID: ctx.sessionID, + guard: "loop", + action: decision.type === "stop" ? "stop" : "correct", + subject: input.tool, + detail: decision.message, + }) yield* Effect.logWarning("model is repeating itself", { sessionID: ctx.sessionID, tool: input.tool, @@ -783,6 +792,7 @@ export const node = LayerNode.make({ service: Service, layer: layer, deps: [ + SessionGuardLog.node, Session.node, Config.node, Snapshot.node, diff --git a/packages/redcode/src/session/prompt.ts b/packages/redcode/src/session/prompt.ts index a22e41a727d1..1259ca5e92b2 100644 --- a/packages/redcode/src/session/prompt.ts +++ b/packages/redcode/src/session/prompt.ts @@ -42,6 +42,7 @@ import { NamedError } from "@reddb-io/redcode-core/util/error" import { SessionProcessor } from "./processor" import { StepBudget } from "./step-budget" import { AuxDeadline } from "./aux-deadline" +import { SessionGuardLog } from "./guard-log" import { SessionStall } from "./stall" import { Tool } from "@/tool/tool" import { Permission } from "@/permission" @@ -138,6 +139,7 @@ const layer = Layer.effect( const plugin = yield* Plugin.Service const commands = yield* Command.Service const config = yield* Config.Service + const guards = yield* SessionGuardLog.Service const permission = yield* Permission.Service const fsys = yield* FSUtil.Service const mcp = yield* MCP.Service @@ -266,9 +268,19 @@ const layer = Layer.effect( : Effect.timeoutOrElse({ duration: Duration.millis(titleMs), orElse: () => - Effect.logWarning(AuxDeadline.message("title", titleMs), { - "session.id": input.session.id, - }).pipe(Effect.as("")), + Effect.gen(function* () { + yield* guards.record({ + sessionID: input.session.id, + guard: "aux", + action: "stop", + subject: "title", + detail: AuxDeadline.message("title", titleMs), + }) + yield* Effect.logWarning(AuxDeadline.message("title", titleMs), { + "session.id": input.session.id, + }) + return "" + }), }), ) const cleaned = text @@ -1176,6 +1188,12 @@ const layer = Layer.effect( // Said once per quiet stretch, not on every poll. if (!warned) { warned = true + yield* guards.record({ + sessionID, + guard: "stall", + action: "warn", + detail: SessionStall.warning(decision.quietMs, limits), + }) yield* Effect.logWarning(SessionStall.warning(decision.quietMs, limits), { "session.id": sessionID, messageID: handle.message.id, @@ -1184,6 +1202,12 @@ const layer = Layer.effect( yield* nap return } + yield* guards.record({ + sessionID, + guard: "stall", + action: "stop", + detail: `stopped: ${decision.reason}`, + }) yield* Effect.logWarning("ending a turn that stopped producing output", { "session.id": sessionID, messageID: handle.message.id, @@ -1219,6 +1243,7 @@ const layer = Layer.effect( limits: StepBudget.limits((yield* config.get()).experimental?.turn_steps), }) if (budget.type === "stop") { + yield* guards.record({ sessionID, guard: "steps", action: "stop", detail: budget.message }) yield* Effect.logWarning("turn exceeded the step ceiling", { "session.id": sessionID, steps: step, @@ -1230,6 +1255,13 @@ const layer = Layer.effect( break } if (budget.type === "wrap-up") { + yield* guards.record({ + sessionID, + guard: "steps", + action: "correct", + subject: `step ${step + 1}`, + detail: `asked for a final report with ${budget.remaining} steps left before the ceiling`, + }) yield* Effect.logWarning("turn is near the step ceiling; asking for a final report", { "session.id": sessionID, steps: step, @@ -1434,6 +1466,7 @@ const layer = Layer.effect( promptOps, publishEvent: events.publish, toolTimeout: (yield* config.get()).experimental?.tool_timeout, + recordGuard: guards.record, ...(lastUser.format?.type === "json_schema" ? { structuredOutputTool: createStructuredOutputTool({ @@ -1829,6 +1862,7 @@ export const node = LayerNode.make({ service: Service, layer: layer, deps: [ + SessionGuardLog.node, SessionStatus.node, Session.node, Agent.node, diff --git a/packages/redcode/src/session/tool-deadline.ts b/packages/redcode/src/session/tool-deadline.ts index 28014bf8699c..2fe75c1efe17 100644 --- a/packages/redcode/src/session/tool-deadline.ts +++ b/packages/redcode/src/session/tool-deadline.ts @@ -50,7 +50,7 @@ export const POLL_MS = 250 */ export const guard = ( self: Effect.Effect, - input: { tool: string; ms: number; waitedMs: () => number }, + input: { tool: string; ms: number; waitedMs: () => number; onExpire?: Effect.Effect }, ): Effect.Effect => Effect.raceFirst( self, @@ -58,6 +58,7 @@ export const guard = ( const start = Date.now() const step = Duration.millis(Math.max(1, Math.min(input.ms, POLL_MS))) while (Date.now() - start - input.waitedMs() < input.ms) yield* Effect.sleep(step) + if (input.onExpire) yield* input.onExpire return yield* Effect.die(new Error(message(input))) }), ) diff --git a/packages/redcode/src/session/tools.ts b/packages/redcode/src/session/tools.ts index ff32a69d061c..4ceabdda1660 100644 --- a/packages/redcode/src/session/tools.ts +++ b/packages/redcode/src/session/tools.ts @@ -27,6 +27,7 @@ import { isRecord } from "@/util/record" import { RuntimeFlags } from "@/effect/runtime-flags" import { OperationHook } from "@reddb-io/redcode-core/operation-hook" import { ToolDeadline } from "./tool-deadline" +import type { SessionGuardLog } from "./guard-log" import { OperationHookBridge } from "@/operation-hook-bridge" import { SessionMessage } from "@reddb-io/redcode-schema/session-message" @@ -55,6 +56,8 @@ export const resolve = Effect.fn("SessionTools.resolve")(function* (input: { publishEvent: EventV2.Interface["publish"] structuredOutputTool?: AITool toolTimeout?: number | false + /** Passed in rather than resolved here: this module is used from callers that own the service. */ + recordGuard: (trip: SessionGuardLog.Trip) => Effect.Effect }) { const tools: Record = {} const run = yield* EffectBridge.make() @@ -129,6 +132,13 @@ export const resolve = Effect.fn("SessionTools.resolve")(function* (input: { tool: toolID, ms: deadline, waitedMs: () => permissionWaitMs(options.toolCallId), + onExpire: input.recordGuard({ + sessionID: input.session.id, + guard: "tool_timeout", + action: "stop", + subject: toolID, + detail: ToolDeadline.message({ tool: toolID, ms: deadline }), + }), }) ).pipe(Effect.exit) if (Exit.isFailure(executed)) { diff --git a/packages/redcode/test/cli/help/__snapshots__/help-snapshots.test.ts.snap b/packages/redcode/test/cli/help/__snapshots__/help-snapshots.test.ts.snap index 3c774f791cd2..f8cd1d9778ba 100644 --- a/packages/redcode/test/cli/help/__snapshots__/help-snapshots.test.ts.snap +++ b/packages/redcode/test/cli/help/__snapshots__/help-snapshots.test.ts.snap @@ -113,6 +113,7 @@ debugging and troubleshooting tools Commands: redcode debug config show resolved configuration + redcode debug guards how often the turn guards intervened, and on what redcode debug lsp LSP debugging utilities redcode debug rg ripgrep debugging utilities redcode debug file file system debugging utilities diff --git a/packages/redcode/test/event-manifest.test.ts b/packages/redcode/test/event-manifest.test.ts index 9e73f6024478..049436629bce 100644 --- a/packages/redcode/test/event-manifest.test.ts +++ b/packages/redcode/test/event-manifest.test.ts @@ -9,12 +9,16 @@ describe("public event manifest", () => { expect(EventManifest.Definitions).toBe(SchemaEventManifest.Definitions) expect(EventManifest.Latest).toBe(SchemaEventManifest.Latest) expect(EventManifest.Durable).toBe(SchemaEventManifest.Durable) - expect(EventManifest.Latest.size).toBe(88) + expect(EventManifest.Latest.size).toBe(89) expect(EventManifest.Latest.get("session.next.step.ended")).toBe(SessionEvent.Step.Ended) expect(EventManifest.Latest.get("todo.updated")).toBe(Todo.Event.Updated) expect(EventManifest.Latest.has("ide.installed")).toBe(false) expect(EventManifest.Latest.has("server.connected")).toBe(true) expect(EventManifest.Latest.has("global.disposed")).toBe(true) + // Live, and public on purpose: a client that wants to show why a turn was cut short reads it + // from the wire rather than from the server's log. + expect(EventManifest.Latest.get("session.next.guard.tripped")).toBe(SessionEvent.Guard.Tripped) + expect(EventManifest.Durable.has("session.next.guard.tripped")).toBe(false) }) test("contains only the current step settlement versions", () => { diff --git a/packages/redcode/test/session/guard-log.test.ts b/packages/redcode/test/session/guard-log.test.ts new file mode 100644 index 000000000000..d08219c06b83 --- /dev/null +++ b/packages/redcode/test/session/guard-log.test.ts @@ -0,0 +1,34 @@ +import { describe, expect, test } from "bun:test" +import { summarize } from "@/session/guard-log" + +describe("guard log", () => { + test("counts each guard and action separately", () => { + // A guard that warns ten times and stops once is a very different picture from one that + // stops ten times, and the whole point of the log is to tell those apart. + const rows = summarize([ + { guard: "stall", action: "warn" }, + { guard: "stall", action: "warn" }, + { guard: "stall", action: "stop" }, + { guard: "loop", action: "correct" }, + ]) + expect(rows).toEqual([ + { guard: "stall", action: "warn", count: 2 }, + { guard: "loop", action: "correct", count: 1 }, + { guard: "stall", action: "stop", count: 1 }, + ]) + }) + + test("puts the loudest first", () => { + // What fires most is what most needs its threshold questioned, so it reads first. + const rows = summarize([ + { guard: "loop", action: "correct" }, + { guard: "tool_timeout", action: "stop" }, + { guard: "tool_timeout", action: "stop" }, + ]) + expect(rows[0]).toEqual({ guard: "tool_timeout", action: "stop", count: 2 }) + }) + + test("says nothing rather than something when nothing fired", () => { + expect(summarize([])).toEqual([]) + }) +}) diff --git a/packages/redcode/test/session/prompt.test.ts b/packages/redcode/test/session/prompt.test.ts index b061bfaf8065..f64adb7ad569 100644 --- a/packages/redcode/test/session/prompt.test.ts +++ b/packages/redcode/test/session/prompt.test.ts @@ -36,6 +36,7 @@ import { SessionSummary } from "../../src/session/summary" import { Instruction } from "../../src/session/instruction" import { SessionProcessor } from "../../src/session/processor" import { SessionPrompt } from "../../src/session/prompt" +import { SessionGuardLog } from "../../src/session/guard-log" import { SessionRevert } from "../../src/session/revert" import { SessionRunState } from "../../src/session/run-state" import { MessageID, PartID, SessionID } from "../../src/session/schema" @@ -176,6 +177,7 @@ const testLLMServerNode = LayerNode.make({ service: TestLLMServer, layer: TestLL const promptRoot = LayerNode.group([ SessionPrompt.node, + SessionGuardLog.node, Session.node, SessionProjector.node, MessageV2.node, @@ -1564,6 +1566,45 @@ it.instance("does not let naming the session hold up the turn", () => 60_000, ) +it.instance("writes down that a guard intervened, so the thresholds can be argued from evidence", () => + Effect.gen(function* () { + // Every threshold in the guards was chosen by argument. This is the record that lets the next + // one be chosen by measurement: which guard fired, on what, how often. + const { llm } = yield* useServerConfig((url) => ({ + ...providerCfg(url), + experimental: { tool_timeout: 500 }, + })) + const registry = yield* ToolRegistry.Service + const { read } = yield* registry.named() + const { ready, restore } = yield* hangUntilAborted(read) + yield* restore + + const prompt = yield* SessionPrompt.Service + const sessions = yield* Session.Service + const guards = yield* SessionGuardLog.Service + const chat = yield* sessions.create({ title: "Pinned" }) + yield* seed(chat.id) + + yield* llm.tool("read", { filePath: "/tmp/whatever" }) + yield* llm.text("that path does not answer") + yield* user(chat.id, "more") + + const fiber = yield* prompt.loop({ sessionID: chat.id }).pipe(Effect.forkChild) + yield* awaitWithTimeout(Deferred.await(ready), "timed out waiting for the tool to start", "10 seconds") + yield* awaitWithTimeout(Fiber.await(fiber), "the turn never finished", "20 seconds") + + const trips = yield* guards.recent() + const timeout = trips.find((trip) => trip.guard === "tool_timeout") + expect(timeout).toBeDefined() + expect(timeout?.action).toBe("stop") + expect(timeout?.subject).toBe("read") + expect(timeout?.sessionID).toBe(chat.id) + // And it aggregates, which is what makes a week of use readable. + expect(yield* guards.summary()).toContainEqual({ guard: "tool_timeout", action: "stop", count: 1 }) + }), + 60_000, +) + it.instance("cancel records MessageAbortedError on interrupted process", () => Effect.gen(function* () { const { llm } = yield* useServerConfig(providerCfg) diff --git a/packages/schema/src/session-event.ts b/packages/schema/src/session-event.ts index b080d06be7fd..9d91c6571a2a 100644 --- a/packages/schema/src/session-event.ts +++ b/packages/schema/src/session-event.ts @@ -162,6 +162,30 @@ export namespace Turn { export type Ended = typeof Ended.Type } +export namespace Guard { + /** + * One of the turn's guards intervened. + * + * Live and observational: the guard has already acted by the time this is published, and the + * action itself reaches the user through the transcript. This exists so the intervention can be + * counted — thresholds were argued into place, and only evidence can argue them out. + */ + export const Tripped = Event.define({ + type: "session.next.guard.tripped", + schema: { + ...Base, + /** Which guard: stall, tool_timeout, loop, steps, aux. */ + guard: Schema.String, + /** What it did: warn (said so, changed nothing), correct (answered the model), stop (ended it). */ + action: Schema.String, + /** The tool, phase, or call it acted on, when there is one. */ + subject: optional(Schema.String), + detail: Schema.String, + }, + }) + export type Tripped = typeof Tripped.Type +} + export const ContextUpdated = Event.define({ type: "session.next.context.updated", ...options, @@ -645,6 +669,7 @@ export const DurableDefinitions = Event.inventory( ) export const Definitions = Event.inventory( + Guard.Tripped, AgentSwitched, ModelSwitched, Moved,