diff --git a/cmd/odek/bug_sweep_b1_cleanup_test.go b/cmd/odek/bug_sweep_b1_cleanup_test.go new file mode 100644 index 0000000..9d3f853 --- /dev/null +++ b/cmd/odek/bug_sweep_b1_cleanup_test.go @@ -0,0 +1,58 @@ +package main + +// Bug-sweep batch 1 (fix/bug-hunt-b1) — B2/B3 regression tests. +// +// RED-first: both failed against the pre-fix dry-run collector, which never +// previewed artifact subtree deletions (the real sweep removes +// ~/.odek/artifacts// by default) and whose log list omitted +// serve.log even though rotateLogs rotates it. + +import ( + "bytes" + "os" + "path/filepath" + "testing" + "time" + + "github.com/BackendStack21/odek/internal/maintenance" +) + +func TestCleanupDryRun_PreviewsArtifactSubtrees(t *testing.T) { + home := t.TempDir() + artDir := filepath.Join(home, "artifacts", "sess-b2") + if err := os.MkdirAll(artDir, 0o755); err != nil { + t.Fatal(err) + } + if err := os.WriteFile(filepath.Join(artDir, "result.txt"), []byte("x"), 0o644); err != nil { + t.Fatal(err) + } + old := time.Now().Add(-48 * time.Hour) + if err := os.Chtimes(artDir, old, old); err != nil { + t.Fatal(err) + } + + cfg := maintenance.Config{ArtifactsMaxAgeHours: 24} + c := collectCleanupCandidates(home, cfg) + for _, a := range c.artifacts { + if a == artDir { + return + } + } + t.Fatalf("dry-run omitted artifact subtree %q that the real sweep deletes; previewed artifacts = %v", artDir, c.artifacts) +} + +func TestCleanupDryRun_IncludesServeLog(t *testing.T) { + home := t.TempDir() + p := filepath.Join(home, "serve.log") + if err := os.WriteFile(p, bytes.Repeat([]byte("a"), 2*1024*1024), 0o644); err != nil { + t.Fatal(err) + } + cfg := maintenance.Config{LogMaxMB: 1} + c := collectCleanupCandidates(home, cfg) + for _, l := range c.logs { + if l == p { + return + } + } + t.Fatalf("dry-run omitted oversized serve.log %q; previewed logs = %v", p, c.logs) +} diff --git a/cmd/odek/bug_sweep_b1_registry_test.go b/cmd/odek/bug_sweep_b1_registry_test.go new file mode 100644 index 0000000..8a37bbf --- /dev/null +++ b/cmd/odek/bug_sweep_b1_registry_test.go @@ -0,0 +1,74 @@ +package main + +// Bug-sweep batch 1 (fix/bug-hunt-b1) — B4 regression test. +// +// RED-first: the registry ring evicted entries[0] regardless of phase, so a +// still-running sub-agent could be evicted under ring pressure; its next +// progress record then auto-created a hollow entry without RunKey, making +// the task invisible to run-filtered snapshots (the reload-restore path). + +import ( + "fmt" + "testing" + "time" +) + +func TestSubagentRegistry_EvictionKeepsLiveEntriesVisible(t *testing.T) { + // Snapshot and restore the process-global registry around the test. + subagentReg.mu.Lock() + savedEntries, savedByID := subagentReg.entries, subagentReg.byID + subagentReg.mu.Unlock() + defer func() { + subagentReg.mu.Lock() + subagentReg.entries, subagentReg.byID = savedEntries, savedByID + subagentReg.mu.Unlock() + }() + + live := newTaskID() + subagentRegistryRecord(&subagentEntry{ + TaskID: live, RunKey: "r1", Goal: "important work", + Phase: "started", Status: "running", + }) + // Overflow the ring with finished entries (evictable by preference). + for i := 0; i < maxSubagentRegistryEntries+10; i++ { + e := &subagentEntry{ + TaskID: fmt.Sprintf("filler-%d-%d", i, time.Now().UnixNano()), + RunKey: "r1", + Phase: "finished", + Status: "success", + } + e.FinishedAt = time.Now() + subagentRegistryRecord(e) + } + + entries := subagentRegistrySnapshot("r1") + var found *subagentEntry + for i := range entries { + if entries[i].TaskID == live { + found = &entries[i] + } + } + if found == nil { + t.Fatalf("live entry evicted while finished entries were evictable (ring=%d)", maxSubagentRegistryEntries) + } + if found.Goal != "important work" || found.RunKey != "r1" { + t.Fatalf("live entry decapitated: goal=%q runKey=%q", found.Goal, found.RunKey) + } + + // A progress record for the (surviving) task must keep it visible in + // the run-filtered snapshot — auto-recreate must not strip RunKey. + subagentRegistryUpdate(live, "r1", func(e *subagentEntry) { e.Step = 2 }) + entries = subagentRegistrySnapshot("r1") + found = nil + for i := range entries { + if entries[i].TaskID == live { + found = &entries[i] + } + } + if found == nil { + t.Fatalf("progress update recreated the entry without RunKey; task invisible in run-filtered snapshot") + } + if found.Step != 2 { + t.Fatalf("progress update not applied: step = %d, want 2", found.Step) + } +} diff --git a/cmd/odek/bug_sweep_b1_relay_test.go b/cmd/odek/bug_sweep_b1_relay_test.go new file mode 100644 index 0000000..c1a3c45 --- /dev/null +++ b/cmd/odek/bug_sweep_b1_relay_test.go @@ -0,0 +1,41 @@ +package main + +// Bug-sweep batch 1 (fix/bug-hunt-b1) — B5 regression test. +// +// RED-first: when a child emitted subagent_finished(status=success) but its +// framed result line failed to parse, the parent done relay unconditionally +// overwrote the terminal state to "failed" and bumped the failed counter — +// the card showed failed-with-cost and both lifetime counters counted the +// same task. + +import "testing" + +func TestSubagentDoneRelay_DoesNotClobberChildReportedSuccess(t *testing.T) { + taskID := newTaskID() + // Child reported success through the telemetry stream: + subagentRegistryRecord(&subagentEntry{ + TaskID: taskID, RunKey: "conn-b1", Phase: "finished", Status: "success", + }) + beforeFailed := subagentStats.failed.Load() + + // Framed result unparseable → parent done-relay reports "failed": + relay := newSubagentDoneRelay(func(v any) error { return nil }, "conn-b1") + relay(0, taskID, "failed") + + entries := subagentRegistrySnapshot("") + var e *subagentEntry + for i := range entries { + if entries[i].TaskID == taskID { + e = &entries[i] + } + } + if e == nil { + t.Fatal("registry entry missing") + } + if e.Status != "success" { + t.Fatalf("child-reported success clobbered to %q by the done relay", e.Status) + } + if after := subagentStats.failed.Load(); after != beforeFailed { + t.Fatalf("failed counter bumped for an already-successful task: %d -> %d", beforeFailed, after) + } +} diff --git a/cmd/odek/bug_sweep_b1_runs_test.go b/cmd/odek/bug_sweep_b1_runs_test.go new file mode 100644 index 0000000..4c62d18 --- /dev/null +++ b/cmd/odek/bug_sweep_b1_runs_test.go @@ -0,0 +1,61 @@ +package main + +// Bug-sweep batch 1 (fix/bug-hunt-b1) — B1 regression test. +// +// RED-first: this failed against the pre-fix handler, which answered +// DELETE /api/runs/{id} with the hardcoded status "cancelled" regardless of +// the run's real (terminal) status, and re-stamped EndedAt via cancelRun. + +import ( + "encoding/json" + "net/http" + "net/http/httptest" + "sync" + "testing" + "time" +) + +func TestRunDelete_TerminalRunReportsRealStatus(t *testing.T) { + run := &serveRun{ + ID: "run-b1-delete-terminal", + SessionID: "sess-b1", + Model: "test-model", + Status: "running", + StartedAt: time.Now().UTC().Add(-time.Minute), + } + run.cond = sync.NewCond(&run.mu) + run.pending = map[string]*approvalRequest{} + registerRun(run) + run.finish("completed", "") + run.mu.Lock() + endedAt := run.EndedAt + run.mu.Unlock() + + rr := httptest.NewRecorder() + req := httptest.NewRequest(http.MethodDelete, "/api/runs/run-b1-delete-terminal", nil) + handleRunByID()(rr, req) + + if rr.Code != http.StatusOK { + t.Fatalf("DELETE status = %d, want 200 (body: %s)", rr.Code, rr.Body.String()) + } + var resp struct { + Status string `json:"status"` + Idle bool `json:"idle"` + RunID string `json:"run_id"` + } + if err := json.Unmarshal(rr.Body.Bytes(), &resp); err != nil { + t.Fatalf("response is not valid JSON: %v (body: %s)", err, rr.Body.String()) + } + if resp.Status != "completed" { + t.Errorf("response status = %q, want the run's real status %q (hardcoded-cancelled lie)", resp.Status, "completed") + } + if !resp.Idle { + t.Errorf("response idle = false, want true for a terminal run") + } + run.mu.Lock() + nowEnded := run.EndedAt + run.mu.Unlock() + if !nowEnded.Equal(endedAt) { + t.Errorf("DELETE on terminal run re-stamped EndedAt: %v -> %v", endedAt, nowEnded) + } +} diff --git a/cmd/odek/cleanup.go b/cmd/odek/cleanup.go index 630c810..986a0e4 100644 --- a/cmd/odek/cleanup.go +++ b/cmd/odek/cleanup.go @@ -114,14 +114,18 @@ func humanBytes(n int64) string { // // maintenance.Sweep has no dry-run mode, so the CLI builds the same candidate // list locally for display only. Media cleanup is not previewed — its -// retention policy lives inside the maintenance package. +// retention policy lives inside the maintenance package. Artifact subtree +// removals ARE previewed (plain age-based deletions), and the log list is +// shared with maintenance.LogRotationNames so preview and rotation can never +// drift apart again. // cleanupCandidates lists what a sweep WOULD remove, per category. type cleanupCandidates struct { - sessions []string - audit []string - plans []string - logs []string + sessions []string + audit []string + plans []string + logs []string + artifacts []string } // collectCleanupCandidates enumerates expired files under home without @@ -140,8 +144,12 @@ func collectCleanupCandidates(home string, cfg maintenance.Config) cleanupCandid // Plans may be nested per chat (plans/chat/), so walk recursively. c.plans = filesOlderThan(filepath.Join(home, "plans"), now.AddDate(0, 0, -cfg.PlansMaxAgeDays), true) } + if cfg.ArtifactsMaxAgeHours > 0 { + // Duration-based cutoff, mirroring sweepArtifacts exactly. + c.artifacts = artifactCandidates(home, time.Now().Add(-time.Duration(cfg.ArtifactsMaxAgeHours)*time.Hour)) + } if cfg.LogMaxMB > 0 { - for _, name := range []string{"schedule.log", "telegram.log"} { + for _, name := range maintenance.LogRotationNames() { p := filepath.Join(home, name) if info, err := os.Stat(p); err == nil && info.Size() > cfg.LogMaxMB*1024*1024 { c.logs = append(c.logs, p) @@ -173,6 +181,31 @@ func sessionCandidates(home string, cutoff time.Time) []string { return out } +// artifactCandidates lists delegate_tasks artifact subtrees whose modtime +// is before cutoff — the same candidates maintenance.sweepArtifacts would +// remove (/artifacts// subtrees). +func artifactCandidates(home string, cutoff time.Time) []string { + dir := filepath.Join(home, "artifacts") + entries, err := os.ReadDir(dir) + if err != nil { + return nil // missing/unreadable dir → no candidates + } + var out []string + for _, e := range entries { + if !e.IsDir() { + continue + } + info, err := e.Info() + if err != nil { + continue + } + if info.ModTime().Before(cutoff) { + out = append(out, filepath.Join(dir, e.Name())) + } + } + return out +} + // filesOlderThan returns the regular files under dir whose modification time // is before cutoff. Session index/metadata files are excluded. Missing // directories yield an empty list. @@ -211,7 +244,7 @@ func filesOlderThan(dir string, cutoff time.Time, recursive bool) []string { // printCleanupDryRun reports the candidate list without removing anything. func printCleanupDryRun(home string, cfg maintenance.Config) { c := collectCleanupCandidates(home, cfg) - if len(c.sessions) == 0 && len(c.audit) == 0 && len(c.plans) == 0 && len(c.logs) == 0 { + if len(c.sessions) == 0 && len(c.audit) == 0 && len(c.plans) == 0 && len(c.logs) == 0 && len(c.artifacts) == 0 { fmt.Println("Dry run: storage is clean — nothing would be removed.") return } @@ -219,6 +252,9 @@ func printCleanupDryRun(home string, cfg maintenance.Config) { fmt.Printf(" sessions: %d\n", len(c.sessions)) fmt.Printf(" audit records: %d\n", len(c.audit)) fmt.Printf(" plans: %d\n", len(c.plans)) + for _, p := range c.artifacts { + fmt.Printf(" artifact subtree: %s\n", p) + } for _, p := range c.logs { fmt.Printf(" log rotated: %s\n", p) } diff --git a/cmd/odek/serve_runs.go b/cmd/odek/serve_runs.go index 44de5e2..471dde8 100644 --- a/cmd/odek/serve_runs.go +++ b/cmd/odek/serve_runs.go @@ -895,8 +895,19 @@ func handleRunByID() http.HandlerFunc { writeAPIJSON(w, http.StatusOK, run.snapshot(true)) return } - cancelRun(run) - writeAPIJSON(w, http.StatusOK, map[string]any{"status": "cancelled", "run_id": id}) + // DELETE = cancel, but a run that already reached a terminal state + // must be left untouched and reported under its REAL status: the + // hardcoded "cancelled" answer lied to clients about completed and + // failed runs, and cancelRun → finish re-stamped EndedAt on them. + idle := run.isTerminal() + if !idle { + cancelRun(run) + } + resp := map[string]any{"run_id": id, "status": run.snapshot(false)["status"]} + if idle { + resp["idle"] = true + } + writeAPIJSON(w, http.StatusOK, resp) } } diff --git a/cmd/odek/subagent_registry.go b/cmd/odek/subagent_registry.go index bbbea9e..2c6f20a 100644 --- a/cmd/odek/subagent_registry.go +++ b/cmd/odek/subagent_registry.go @@ -94,8 +94,21 @@ func subagentRegistryRecord(e *subagentEntry) { subagentReg.entries = append(subagentReg.entries, &cp) subagentReg.byID[e.TaskID] = &cp if len(subagentReg.entries) > maxSubagentRegistryEntries { - oldest := subagentReg.entries[0] - subagentReg.entries = subagentReg.entries[1:] + // Prefer evicting the oldest FINISHED entry: ring pressure must not + // erase a still-running task's card (its next progress record would + // recreate a hollow entry without RunKey, making it invisible to + // run-filtered snapshots — the reload-restore path this registry + // exists for). Fall back to the oldest entry only when every entry + // is live (unreachable in practice: concurrency ≪ ring size). + evictIdx := 0 + for i, e := range subagentReg.entries { + if e.Phase == "finished" { + evictIdx = i + break + } + } + oldest := subagentReg.entries[evictIdx] + subagentReg.entries = append(subagentReg.entries[:evictIdx], subagentReg.entries[evictIdx+1:]...) delete(subagentReg.byID, oldest.TaskID) } } @@ -164,9 +177,11 @@ func mergeEntry(dst, src *subagentEntry) { // subagentRegistryUpdate applies fn to the entry with the given task_id // (no-op when absent). New entries are auto-created so a progress line that -// races its started record still lands. -func subagentRegistryUpdate(taskID string, fn func(*subagentEntry)) { - subagentRegistryRecord(&subagentEntry{TaskID: taskID}) +// races its started record still lands; runKey stamps such recreated entries +// (eviction race / out-of-order arrival) so run-filtered snapshots keep +// seeing the task. +func subagentRegistryUpdate(taskID, runKey string, fn func(*subagentEntry)) { + subagentRegistryRecord(&subagentEntry{TaskID: taskID, RunKey: runKey}) subagentReg.mu.Lock() defer subagentReg.mu.Unlock() if e, ok := subagentReg.byID[taskID]; ok { @@ -261,7 +276,7 @@ func newSubagentTelemetryRelay(send func(v any) error, runKey string) func(taskI BudgetCostUSD: rec.BudgetCostUSD, }) case "subagent_progress": - subagentRegistryUpdate(taskID, func(e *subagentEntry) { + subagentRegistryUpdate(taskID, runKey, func(e *subagentEntry) { e.Phase = "active" e.Step = rec.Step e.LastTool = rec.Tool @@ -287,7 +302,7 @@ func newSubagentTelemetryRelay(send func(v any) error, runKey string) func(taskI } }) case "subagent_finished": - subagentRegistryUpdate(taskID, func(e *subagentEntry) { + subagentRegistryUpdate(taskID, runKey, func(e *subagentEntry) { e.Phase = "finished" e.Status = rec.Status e.Iterations = rec.Iterations @@ -319,7 +334,7 @@ func newSubagentTelemetryRelay(send func(v any) error, runKey string) func(taskI // itself never reaches this relay). Merge-only — phase, // status, and lifetime counters stay owned by the // subagent_finished / done-relay paths. - subagentRegistryUpdate(taskID, func(e *subagentEntry) { + subagentRegistryUpdate(taskID, runKey, func(e *subagentEntry) { if rec.CostUSD > 0 { e.CostUSD = rec.CostUSD } @@ -469,14 +484,25 @@ func newSubagentDoneRelay(send func(v any) error, runKey string) func(taskIdx in // Update (auto-creates) rather than Record: Record's re-record // path restores accumulated state, which would clobber the // terminal transition on an existing entry. - subagentRegistryUpdate(taskID, func(e *subagentEntry) { + // First terminal report wins: this relay exists for children that + // died without reporting (or whose framed result never parsed). When + // the child itself already reported a terminal status via its + // telemetry stream, overwriting it flipped a reported success to + // "failed" on the card AND double-counted the task in the lifetime + // counters. + alreadyTerminal := false + subagentRegistryUpdate(taskID, runKey, func(e *subagentEntry) { + if e.Phase == "finished" && (e.Status == "success" || e.Status == "partial") { + alreadyTerminal = true + return + } e.Phase = "finished" e.Status = status e.FinishedAt = time.Now() }) // A user-initiated cancel is neither success nor failure for the // lifetime counters; every other no-result outcome is a failure. - if status != "cancelled" { + if !alreadyTerminal && status != "cancelled" { subagentStats.failed.Add(1) } // Fan the terminal state out to the UI. diff --git a/cmd/odek/subagent_registry_test.go b/cmd/odek/subagent_registry_test.go index 1fedf9b..bcb5e94 100644 --- a/cmd/odek/subagent_registry_test.go +++ b/cmd/odek/subagent_registry_test.go @@ -22,7 +22,7 @@ func TestSubagentRegistry_RecordUpdateSnapshot(t *testing.T) { resetSubagentRegistry() subagentRegistryRecord(&subagentEntry{TaskID: "task-1", RunKey: "conn-1", Goal: "write tests", Phase: "started", Status: "running"}) - subagentRegistryUpdate("task-1", func(e *subagentEntry) { + subagentRegistryUpdate("task-1", "", func(e *subagentEntry) { e.Phase = "active" e.LastTool = "read_file" e.Step = 2 @@ -74,7 +74,7 @@ func TestSubagentRegistry_ConcurrentAccess(t *testing.T) { id := "task-c" subagentRegistryRecord(&subagentEntry{TaskID: id, RunKey: "k"}) for j := 0; j < 50; j++ { - subagentRegistryUpdate(id, func(e *subagentEntry) { e.Step++ }) + subagentRegistryUpdate(id, "", func(e *subagentEntry) { e.Step++ }) _ = subagentRegistrySnapshot("") } }(i) diff --git a/internal/maintenance/maintenance.go b/internal/maintenance/maintenance.go index a5fe9be..17a066a 100644 --- a/internal/maintenance/maintenance.go +++ b/internal/maintenance/maintenance.go @@ -264,14 +264,22 @@ func sweepAudit(home string, maxAgeDays int) (int, error) { return removed, nil } -// rotateLogs rotates /telegram.log (when it exists) and -// /schedule.log when they exceed maxMB: the current log is renamed to -// .1 (replacing any previous generation) and a fresh empty log is -// created. One backup generation only. Returns the rotated log paths. +// LogRotationNames lists the log files rotateLogs may rotate. Shared with +// the cleanup dry-run preview (cmd/odek) so the two can never drift again — +// serve.log was once rotated by the real sweep while the preview only knew +// about two logs. +func LogRotationNames() []string { + return []string{"telegram.log", "schedule.log", "serve.log"} +} + +// rotateLogs rotates each log named by LogRotationNames when it exceeds +// maxMB: the current log is renamed to .1 (replacing any previous +// generation) and a fresh empty log is created. One backup generation only. +// Returns the rotated log paths. func rotateLogs(home string, maxMB int64) ([]string, error) { limit := maxMB << 20 var rotated []string - for _, name := range []string{"telegram.log", "schedule.log", "serve.log"} { + for _, name := range LogRotationNames() { path := filepath.Join(home, name) info, err := os.Stat(path) if err != nil {