diff --git a/cli/selftune/sync.ts b/cli/selftune/sync.ts index de01acb..7a62eea 100644 --- a/cli/selftune/sync.ts +++ b/cli/selftune/sync.ts @@ -72,6 +72,11 @@ export interface SyncStepResult { skipped: number; } +export interface SyncPhaseTiming { + phase: string; + elapsed_ms: number; +} + export interface SyncResult { since: string | null; dry_run: boolean; @@ -87,6 +92,8 @@ export interface SyncResult { repaired_records: number; codex_repaired_records: number; }; + timings: SyncPhaseTiming[]; + total_elapsed_ms: number; } export interface SyncOptions { @@ -107,6 +114,8 @@ export interface SyncOptions { rebuildSkillUsage: boolean; } +export type SyncProgressCallback = (message: string) => void; + export interface SyncDeps { syncClaude?: (options: SyncOptions) => SyncStepResult; syncCodex?: (options: SyncOptions) => SyncStepResult; @@ -139,14 +148,29 @@ export function createDefaultSyncOptions(overrides: Partial = {}): }; } -function syncClaudeSource(options: SyncOptions): SyncStepResult { +/** Shared file-list cache so repair can reuse the ingest-phase scan. */ +interface FileListCache { + claudeTranscripts?: string[]; + codexRollouts?: string[]; +} + +function syncClaudeSource( + options: SyncOptions, + onProgress?: SyncProgressCallback, + cache?: FileListCache, +): SyncStepResult { if (!existsSync(options.projectsDir)) { return { available: false, scanned: 0, synced: 0, skipped: 0 }; } + onProgress?.("scanning Claude transcripts..."); const transcriptFiles = findTranscriptFiles(options.projectsDir, options.since); + if (cache) cache.claudeTranscripts = transcriptFiles; + const alreadyIngested = options.force ? new Set() : loadMarker(CLAUDE_CODE_MARKER); const pending = transcriptFiles.filter((f) => !alreadyIngested.has(f)); + onProgress?.(`found ${transcriptFiles.length} transcripts, ${pending.length} pending`); + const newIngested = new Set(); let synced = 0; let skipped = 0; @@ -180,14 +204,23 @@ function syncClaudeSource(options: SyncOptions): SyncStepResult { }; } -function syncCodexSource(options: SyncOptions): SyncStepResult { +function syncCodexSource( + options: SyncOptions, + onProgress?: SyncProgressCallback, + cache?: FileListCache, +): SyncStepResult { + onProgress?.("scanning Codex rollouts..."); const rolloutFiles = findRolloutFiles(options.codexHome, options.since); + if (cache) cache.codexRollouts = rolloutFiles; + if (rolloutFiles.length === 0 && !existsSync(join(options.codexHome, "sessions"))) { return { available: false, scanned: 0, synced: 0, skipped: 0 }; } const alreadyIngested = options.force ? new Set() : loadMarker(CODEX_INGEST_MARKER); const pending = rolloutFiles.filter((f) => !alreadyIngested.has(f)); + onProgress?.(`found ${rolloutFiles.length} rollouts, ${pending.length} pending`); + const skillNames = findCodexSkillNames(); const newIngested = new Set(); let synced = 0; @@ -216,11 +249,15 @@ function syncCodexSource(options: SyncOptions): SyncStepResult { }; } -function syncOpenCodeSource(options: SyncOptions): SyncStepResult { +function syncOpenCodeSource( + options: SyncOptions, + onProgress?: SyncProgressCallback, +): SyncStepResult { if (!existsSync(options.opencodeDataDir)) { return { available: false, scanned: 0, synced: 0, skipped: 0 }; } + onProgress?.("scanning OpenCode sessions..."); const dbPath = join(options.opencodeDataDir, "opencode.db"); const storageDir = join(options.opencodeDataDir, "storage"); const skillNames = findOpenCodeSkillNames(); @@ -237,6 +274,7 @@ function syncOpenCodeSource(options: SyncOptions): SyncStepResult { const alreadyIngested = options.force ? new Set() : loadMarker(OPENCODE_INGEST_MARKER); const pending = allSessions.filter((session) => !alreadyIngested.has(session.session_id)); + onProgress?.(`found ${allSessions.length} sessions, ${pending.length} pending`); const newIngested = new Set(); for (const session of pending) { @@ -256,16 +294,21 @@ function syncOpenCodeSource(options: SyncOptions): SyncStepResult { }; } -function syncOpenClawSource(options: SyncOptions): SyncStepResult { +function syncOpenClawSource( + options: SyncOptions, + onProgress?: SyncProgressCallback, +): SyncStepResult { if (!existsSync(options.openclawAgentsDir)) { return { available: false, scanned: 0, synced: 0, skipped: 0 }; } + onProgress?.("scanning OpenClaw sessions..."); const sinceTs = options.since ? options.since.getTime() : null; const allSessions = findOpenClawSessions(options.openclawAgentsDir, sinceTs); const skillNames = findOpenClawSkillNames(options.openclawAgentsDir); const alreadyIngested = options.force ? new Set() : loadMarker(OPENCLAW_INGEST_MARKER); const pending = allSessions.filter((session) => !alreadyIngested.has(session.sessionId)); + onProgress?.(`found ${allSessions.length} sessions, ${pending.length} pending`); const newIngested = new Set(); let synced = 0; let skipped = 0; @@ -293,13 +336,26 @@ function syncOpenClawSource(options: SyncOptions): SyncStepResult { }; } -function rebuildSkillUsageOverlay(options: SyncOptions): { +function rebuildSkillUsageOverlay( + options: SyncOptions, + onProgress?: SyncProgressCallback, + cache?: FileListCache, +): { repairedSessions: number; repairedRecords: number; codexRepairedRecords: number; } { - const transcriptPaths = findTranscriptFiles(options.projectsDir, options.since); - const rolloutPaths = findRolloutFiles(options.codexHome, options.since); + // Reuse cached file lists from ingest phase when available to avoid re-walking the filesystem + const transcriptPaths = + cache?.claudeTranscripts ?? findTranscriptFiles(options.projectsDir, options.since); + const rolloutPaths = cache?.codexRollouts ?? findRolloutFiles(options.codexHome, options.since); + + const reusedClaude = cache?.claudeTranscripts ? " (cached)" : ""; + const reusedCodex = cache?.codexRollouts ? " (cached)" : ""; + onProgress?.( + `repairing from ${transcriptPaths.length} transcripts${reusedClaude}, ${rolloutPaths.length} rollouts${reusedCodex}`, + ); + const rawSkillRecords = readJsonl(options.skillLogPath); const { repairedRecords, repairedSessionIds } = rebuildSkillUsageFromTranscripts( transcriptPaths, @@ -326,6 +382,10 @@ function rebuildSkillUsageOverlay(options: SyncOptions): { ); } + onProgress?.( + `repaired ${repairedRecords.length} records across ${repairedSessionIds.size} sessions`, + ); + return { repairedSessions: repairedSessionIds.size, repairedRecords: repairedRecords.length, @@ -333,30 +393,75 @@ function rebuildSkillUsageOverlay(options: SyncOptions): { }; } -export function syncSources(options: SyncOptions, deps: SyncDeps = {}): SyncResult { - const runClaude = deps.syncClaude ?? syncClaudeSource; - const runCodex = deps.syncCodex ?? syncCodexSource; - const runOpenCode = deps.syncOpenCode ?? syncOpenCodeSource; - const runOpenClaw = deps.syncOpenClaw ?? syncOpenClawSource; - const runRepair = deps.rebuildSkillUsage ?? rebuildSkillUsageOverlay; +function timePhase(name: string, fn: () => T, timings: SyncPhaseTiming[]): T { + const start = performance.now(); + const result = fn(); + timings.push({ phase: name, elapsed_ms: Math.round(performance.now() - start) }); + return result; +} + +export function syncSources( + options: SyncOptions, + deps: SyncDeps = {}, + onProgress?: SyncProgressCallback, +): SyncResult { + const totalStart = performance.now(); + const timings: SyncPhaseTiming[] = []; + const cache: FileListCache = {}; + + const runClaude = deps.syncClaude; + const runCodex = deps.syncCodex; + const runOpenCode = deps.syncOpenCode; + const runOpenClaw = deps.syncOpenClaw; + const runRepair = deps.rebuildSkillUsage; + + const disabledStep: SyncStepResult = { available: false, scanned: 0, synced: 0, skipped: 0 }; + + onProgress?.("starting sync..."); const claude = options.syncClaude - ? runClaude(options) - : { available: false, scanned: 0, synced: 0, skipped: 0 }; + ? timePhase( + "claude", + () => (runClaude ? runClaude(options) : syncClaudeSource(options, onProgress, cache)), + timings, + ) + : disabledStep; + const codex = options.syncCodex - ? runCodex(options) - : { available: false, scanned: 0, synced: 0, skipped: 0 }; + ? timePhase( + "codex", + () => (runCodex ? runCodex(options) : syncCodexSource(options, onProgress, cache)), + timings, + ) + : disabledStep; + const opencode = options.syncOpenCode - ? runOpenCode(options) - : { available: false, scanned: 0, synced: 0, skipped: 0 }; + ? timePhase( + "opencode", + () => (runOpenCode ? runOpenCode(options) : syncOpenCodeSource(options, onProgress)), + timings, + ) + : disabledStep; + const openclaw = options.syncOpenClaw - ? runOpenClaw(options) - : { available: false, scanned: 0, synced: 0, skipped: 0 }; + ? timePhase( + "openclaw", + () => (runOpenClaw ? runOpenClaw(options) : syncOpenClawSource(options, onProgress)), + timings, + ) + : disabledStep; const repair = options.rebuildSkillUsage - ? runRepair(options) + ? timePhase( + "repair", + () => + runRepair ? runRepair(options) : rebuildSkillUsageOverlay(options, onProgress, cache), + timings, + ) : { repairedSessions: 0, repairedRecords: 0, codexRepairedRecords: 0 }; + const totalElapsed = Math.round(performance.now() - totalStart); + return { since: options.since ? options.since.toISOString() : null, dry_run: options.dryRun, @@ -367,9 +472,25 @@ export function syncSources(options: SyncOptions, deps: SyncDeps = {}): SyncResu repaired_records: repair.repairedRecords, codex_repaired_records: repair.codexRepairedRecords, }, + timings, + total_elapsed_ms: totalElapsed, }; } +function formatMs(ms: number): string { + if (ms < 1000) return `${ms}ms`; + return `${(ms / 1000).toFixed(1)}s`; +} + +function formatStepLine(label: string, step: SyncStepResult, timing?: SyncPhaseTiming): string { + if (!step.available) return ` ${label}: not available`; + const parts = [`scanned ${step.scanned}`]; + if (step.synced > 0) parts.push(`synced ${step.synced}`); + if (step.skipped > 0) parts.push(`skipped ${step.skipped}`); + const time = timing ? ` (${formatMs(timing.elapsed_ms)})` : ""; + return ` ${label}: ${parts.join(", ")}${time}`; +} + export function cliMain(): void { const { values } = parseArgs({ options: { @@ -388,6 +509,7 @@ export function cliMain(): void { "no-opencode": { type: "boolean", default: false }, "no-openclaw": { type: "boolean", default: false }, "no-repair": { type: "boolean", default: false }, + json: { type: "boolean", default: false }, help: { type: "boolean", short: "h", default: false }, }, strict: true, @@ -415,6 +537,7 @@ Options: --no-opencode Skip OpenCode ingest --no-openclaw Skip OpenClaw ingest --no-repair Skip rebuilt skill-usage overlay + --json Output raw JSON instead of human-readable summary -h, --help Show this help`); process.exit(0); } @@ -428,6 +551,23 @@ Options: } } + // JSON output: explicit --json flag, or auto when stdout is not a TTY (preserves contract for automation) + const jsonOutput = (values.json ?? false) || !process.stdout.isTTY; + + const onProgress: SyncProgressCallback | undefined = jsonOutput + ? undefined + : (msg) => { + process.stderr.write(` ${msg}\n`); + }; + + if (!jsonOutput) { + const flags: string[] = []; + if (values.force) flags.push("--force"); + if (values["dry-run"]) flags.push("--dry-run"); + if (since) flags.push(`--since ${values.since}`); + process.stderr.write(`selftune sync${flags.length ? ` ${flags.join(" ")}` : ""}\n`); + } + const result = syncSources( createDefaultSyncOptions({ projectsDir: values["projects-dir"] ?? CLAUDE_CODE_PROJECTS_DIR, @@ -446,9 +586,40 @@ Options: syncOpenClaw: !(values["no-openclaw"] ?? false), rebuildSkillUsage: !(values["no-repair"] ?? false), }), + {}, + onProgress, ); - console.log(JSON.stringify(result, null, 2)); + if (jsonOutput) { + console.log(JSON.stringify(result, null, 2)); + } else { + const timingMap = new Map(result.timings.map((t) => [t.phase, t])); + + process.stderr.write("\nSources:\n"); + process.stderr.write( + `${formatStepLine("Claude", result.sources.claude, timingMap.get("claude"))}\n`, + ); + process.stderr.write( + `${formatStepLine("Codex", result.sources.codex, timingMap.get("codex"))}\n`, + ); + process.stderr.write( + `${formatStepLine("OpenCode", result.sources.opencode, timingMap.get("opencode"))}\n`, + ); + process.stderr.write( + `${formatStepLine("OpenClaw", result.sources.openclaw, timingMap.get("openclaw"))}\n`, + ); + + if (result.repair.ran) { + const repairTiming = timingMap.get("repair"); + const repairTime = repairTiming ? ` (${formatMs(repairTiming.elapsed_ms)})` : ""; + process.stderr.write( + `\nRepair: ${result.repair.repaired_records} records, ` + + `${result.repair.repaired_sessions} sessions${repairTime}\n`, + ); + } + + process.stderr.write(`\nDone in ${formatMs(result.total_elapsed_ms)}\n`); + } } if (import.meta.main) { diff --git a/cli/selftune/utils/query-filter.ts b/cli/selftune/utils/query-filter.ts index 34ccec0..a4b144c 100644 --- a/cli/selftune/utils/query-filter.ts +++ b/cli/selftune/utils/query-filter.ts @@ -4,6 +4,9 @@ import type { QueryLogRecord, SkillUsageRecord } from "../types.js"; const NON_USER_QUERY_PREFIXES = [ "", "", + "", + "", + "", "", "", "", @@ -21,11 +24,29 @@ const NON_USER_QUERY_PREFIXES = [ "Continue from where you left off.", "You are an evaluation assistant.", "You are a skill description optimizer for an AI agent routing system.", + "The following skills are available", +] as const; + +/** + * Regex patterns for wrapper/hook pipeline artifacts that are never real user prompts. + * These fire after prefix checks and cover structured hook callback lines. + */ +const NON_USER_QUERY_PATTERNS = [ + // Hook callback output lines (e.g. "SessionStart:startup hook success: ...") + // "Stop" excluded from general alternation — too common as English word. + /^(SessionStart|UserPromptSubmit|PreToolUse|PostToolUse):/, + // Stop hook callbacks follow a structured shape: "Stop:" + lowercase/callback text + /^Stop:(session |cleanup |hook |Callback )/, + // Injected git context blocks + /^gitStatus:\s/, ] as const; const LEADING_WRAPPED_QUERY_TAGS = [ "system_instruction", "system-instruction", + "system-reminder", + "available-deferred-tools", + "fast_mode_info", "task-notification", "teammate-message", "local-command-caveat", @@ -65,7 +86,8 @@ export function extractActionableQueryText(query: string): string | null { const isBlocked = SKIP_PREFIXES.some((prefix) => candidate.startsWith(prefix)) || - NON_USER_QUERY_PREFIXES.some((prefix) => candidate.startsWith(prefix)); + NON_USER_QUERY_PREFIXES.some((prefix) => candidate.startsWith(prefix)) || + NON_USER_QUERY_PATTERNS.some((pattern) => pattern.test(candidate)); return isBlocked ? null : candidate; } diff --git a/tests/status/status.test.ts b/tests/status/status.test.ts index 6d68fa9..853ff20 100644 --- a/tests/status/status.test.ts +++ b/tests/status/status.test.ts @@ -276,6 +276,50 @@ describe("computeStatus", () => { expect(result.unmatchedQueries).toBe(1); }); + test("filters wrapper/system-reminder noise from unmatched query counts", () => { + const sid = "sess-1"; + const telemetry = [makeTelemetry({ session_id: sid })]; + const skillRecords = [ + makeSkillRecord({ + session_id: sid, + skill_name: "my-skill", + triggered: true, + query: "matched query", + }), + ]; + const queryRecords = [ + makeQuery({ session_id: sid, query: "matched query" }), + // Wrapper/system noise that should NOT inflate unmatched counts + makeQuery({ + session_id: sid, + query: "\nPAI Dynamic Context\n", + }), + makeQuery({ + session_id: sid, + query: "\nNotebookEdit\n", + }), + makeQuery({ + session_id: sid, + query: "SessionStart:startup hook success: loaded", + }), + makeQuery({ + session_id: sid, + query: "UserPromptSubmit:Callback hook success: Success", + }), + makeQuery({ + session_id: sid, + query: "gitStatus: This is the git status at the start", + }), + // This IS a real unmatched user query + makeQuery({ session_id: sid, query: "real unmatched prompt" }), + ]; + + const result = computeStatus(telemetry, skillRecords, queryRecords, [], makeDoctorResult()); + + // Only "real unmatched prompt" should count — all noise should be filtered + expect(result.unmatchedQueries).toBe(1); + }); + test("all-false skill checks become critical once sample threshold is met", () => { const sid = "sess-1"; const telemetry = [makeTelemetry({ session_id: sid, skills_triggered: [] })]; diff --git a/tests/sync.test.ts b/tests/sync.test.ts index 1952858..e6f3d6c 100644 --- a/tests/sync.test.ts +++ b/tests/sync.test.ts @@ -1,6 +1,11 @@ import { describe, expect, test } from "bun:test"; -import { type SyncOptions, type SyncStepResult, syncSources } from "../cli/selftune/sync.js"; +import { + type SyncOptions, + type SyncProgressCallback, + type SyncStepResult, + syncSources, +} from "../cli/selftune/sync.js"; const baseOptions: SyncOptions = { projectsDir: "/tmp/claude-projects", @@ -90,4 +95,92 @@ describe("syncSources", () => { codex_repaired_records: 0, }); }); + + test("includes per-phase timings", () => { + const result = syncSources(baseOptions, { + syncClaude: () => step({ scanned: 5 }), + syncCodex: () => step({ scanned: 3 }), + syncOpenCode: () => step({ scanned: 1 }), + syncOpenClaw: () => step({ scanned: 2 }), + rebuildSkillUsage: () => ({ + repairedSessions: 0, + repairedRecords: 0, + codexRepairedRecords: 0, + }), + }); + + expect(result.timings).toBeArray(); + expect(result.timings.length).toBe(5); + const phases = result.timings.map((t) => t.phase); + expect(phases).toEqual(["claude", "codex", "opencode", "openclaw", "repair"]); + for (const timing of result.timings) { + expect(timing.elapsed_ms).toBeGreaterThanOrEqual(0); + } + expect(result.total_elapsed_ms).toBeGreaterThanOrEqual(0); + }); + + test("timings only include enabled phases", () => { + const result = syncSources( + { + ...baseOptions, + syncCodex: false, + syncOpenCode: false, + syncOpenClaw: false, + rebuildSkillUsage: false, + }, + { + syncClaude: () => step({ scanned: 1 }), + }, + ); + + expect(result.timings.length).toBe(1); + expect(result.timings[0].phase).toBe("claude"); + }); + + test("calls progress callback for each phase", () => { + const messages: string[] = []; + const onProgress: SyncProgressCallback = (msg) => messages.push(msg); + + syncSources( + { + ...baseOptions, + syncCodex: false, + syncOpenCode: false, + syncOpenClaw: false, + rebuildSkillUsage: false, + }, + { + syncClaude: () => step({ scanned: 2 }), + }, + onProgress, + ); + + expect(messages.length).toBeGreaterThanOrEqual(1); + expect(messages[0]).toBe("starting sync..."); + }); + + test("progress callback receives messages from real source steps", () => { + // When deps are NOT provided, syncSources uses the real implementations + // which call onProgress. We test by mocking just enough for the real + // functions to hit the "not available" early return. + const messages: string[] = []; + const onProgress: SyncProgressCallback = (msg) => messages.push(msg); + + syncSources( + { + ...baseOptions, + // Point at non-existent dirs so real implementations return early + projectsDir: "/tmp/nonexistent-claude-test", + codexHome: "/tmp/nonexistent-codex-test", + opencodeDataDir: "/tmp/nonexistent-opencode-test", + openclawAgentsDir: "/tmp/nonexistent-openclaw-test", + rebuildSkillUsage: false, + }, + {}, + onProgress, + ); + + // Should have at least "starting sync..." and scan attempts + expect(messages[0]).toBe("starting sync..."); + }); }); diff --git a/tests/utils/query-filter.test.ts b/tests/utils/query-filter.test.ts index 9479a9d..68e1257 100644 --- a/tests/utils/query-filter.test.ts +++ b/tests/utils/query-filter.test.ts @@ -29,6 +29,53 @@ describe("isActionableQueryText", () => { ).toBe(false); }); + test("rejects wrapper/system-reminder and deferred-tools noise", () => { + // Pure system-reminder block (no user content after) + expect( + isActionableQueryText("\nPAI Dynamic Context loaded\n"), + ).toBe(false); + + // Available deferred tools listing + expect( + isActionableQueryText( + "\nNotebookEdit\nWebFetch\n", + ), + ).toBe(false); + + // Fast mode info block + expect( + isActionableQueryText("\nFast mode uses the same model\n"), + ).toBe(false); + + // Skill listing injection + expect( + isActionableQueryText("The following skills are available for use with the Skill tool:"), + ).toBe(false); + }); + + test("rejects hook callback output lines", () => { + expect( + isActionableQueryText("SessionStart:startup hook success: PAI loaded"), + ).toBe(false); + expect(isActionableQueryText("UserPromptSubmit:Callback hook success: Success")).toBe(false); + expect(isActionableQueryText("PreToolUse:Read hook returned: OK")).toBe(false); + expect(isActionableQueryText("PostToolUse:Bash hook returned: OK")).toBe(false); + expect(isActionableQueryText("Stop:session cleanup completed")).toBe(false); + expect(isActionableQueryText("Stop:Callback hook success: OK")).toBe(false); + expect(isActionableQueryText("Stop:hook finalize done")).toBe(false); + }); + + test("preserves user prompts starting with Stop:", () => { + expect(isActionableQueryText("Stop: using the old API and migrate this")).toBe(true); + expect(isActionableQueryText("Stop the deployment pipeline")).toBe(true); + }); + + test("rejects injected git context blocks", () => { + expect( + isActionableQueryText("gitStatus: This is the git status at the start of the conversation."), + ).toBe(false); + }); + test("rejects empty and non-string values", () => { expect(isActionableQueryText(" ")).toBe(false); expect(isActionableQueryText("-")).toBe(false); @@ -40,6 +87,22 @@ describe("isActionableQueryText", () => { expect(isActionableQueryText(wrapped)).toBe(true); expect(extractActionableQueryText(wrapped)).toBe("fix the dashboard"); }); + + test("strips system-reminder wrappers to find real user content", () => { + const wrapped = + "\nPAI Dynamic Context loaded\n\n\nfix the bug"; + expect(isActionableQueryText(wrapped)).toBe(true); + expect(extractActionableQueryText(wrapped)).toBe("fix the bug"); + }); + + test("strips multiple stacked wrapper tags to find real user content", () => { + const wrapped = + "context\n" + + "tools list\n\n" + + "deploy to production"; + expect(isActionableQueryText(wrapped)).toBe(true); + expect(extractActionableQueryText(wrapped)).toBe("deploy to production"); + }); }); describe("filterActionableQueryRecords", () => {