diff --git a/docs/logs/engineering-log.md b/docs/logs/engineering-log.md index 0b025504..0e9fb86b 100644 --- a/docs/logs/engineering-log.md +++ b/docs/logs/engineering-log.md @@ -5906,3 +5906,77 @@ Skipped creating separate issues for Op/EventMsg protocol (already covered by SS the touched `INDEX.md` files, the three corrected investigation files, and this log against `test -e` (758 links, 0 dead). This is documentation only: no runtime, API, or test behavior changed. + +# 2026-09-05 (Issue #1370 rewind message truncation and live mirror repair) + +- Cause: `RestoreRewindPoint` truncated `conversation_messages` by comparing + the rewind point's run-local tool-call step (`RewindPoint.Step`, set in + `runner_step_engine.go`) against `conversation_messages.step`, a + conversation-wide message index shared across every run on that + conversation. Rewinding to a point in a conversation's second (or later) + run deleted the first run's later messages too. Separately, the runner's + in-memory conversation mirror (populated at each run's completion and + served by `ConversationMessagesSnapshot`/`GET /messages`) was never + invalidated by rewind, so the live daemon kept serving pre-rewind history + and the next run re-persisted it over the truncated DB. +- Fix: `RewindPoint` gained `MessageBoundary`, the conversation-wide index of + the assistant message carrying the rewound tool call, recorded at capture + time in the step engine (see the followup entry below for a correction to + this value). `RestoreRewindPoint` truncates by `step >= MessageBoundary` + when it is recorded; points captured before this field existed + (`MessageBoundary == 0`) fall back to the legacy step comparison with a + logged warning instead of silently over-deleting. + `Runner.InvalidateConversationHistory` drops the in-memory mirror entry + for a conversation; the rewind HTTP handler calls it immediately after a + successful restore. +- Regression: a store-level test proves a two-run conversation's rewind keeps + run 1's messages plus run 2's user prompt and tool-call message, + truncating only what follows; an HTTP-level test drives two real runs + through the handler and proves `GET /messages` reflects the truncation + immediately; a third test drives a real three-run `Runner` flow and proves + the run following a rewind does not resurrect the truncated tool result or + final answer in its LLM request. Related: #1303 describes the same + resurrection symptom from a different angle (workspace population, TUI + JSON tags) and remains open. + +# 2026-09-05 (Issue #1370 followup: dangling assistant tool_calls after restore) + +- Cause: the boundary above (`len(messages)` at capture time) pointed just + past the assistant message carrying the rewound tool call, so a restore + kept that assistant message while deleting only its tool result. Real + providers (OpenAI et al.) reject an assistant message with `tool_calls` + that isn't immediately followed by matching tool messages; the fake/stub + providers this repo's tests use do not enforce that, so the bug shipped + with green tests. Caught in review before merge stabilized. +- Fix: `MessageBoundary` is now the conversation-wide index of the assistant + message itself (`assistantToolCallIndex`, captured immediately after that + message is appended in `runner_step_engine.go`), so restore deletes that + message and everything after it. Parallel tool calls issued in one + assistant turn all capture the same index, since they share one assistant + message. `RestoreRewindPoint`'s truncation query and its + unset-boundary fallback are unchanged; only the captured value changed. +- Regression: a new test drives a real single-turn run with two parallel + tool calls through the actual capture path and restores using either + call's point, asserting both points share one boundary, the last + persisted message is never an assistant message with tool_calls, and no + tool message lacks a preceding assistant tool_calls entry for its ID. + +# 2026-09-05 (Issue #1370 followup: rewind_points prune deleted unrelated older points) + +- Cause: found by live verification on main after #1378 merged. + `RestoreRewindPoint`'s future-point pruning query also compared + `point.Step`, the same run-local tool-call counter whose misuse in message + truncation this issue already fixed. Step restarts every run, so run 2's + edit point (step 1 within run 2) and run 1's write point (also step 1 + within run 1, an unrelated run) collided: restoring the edit point deleted + the write point too, and a later restore to that still-valid older point + returned "not found". +- Fix: pruning now uses `MessageBoundary` when recorded -- a point is + superseded only by a strictly greater boundary, or an equal boundary + (parallel tool calls sharing one assistant message) captured later + (`created_at`); the target is always excluded. Falls back to the legacy + step predicate only when the target has no recorded boundary, matching + the existing message-truncation fallback. +- Regression: `TestRestoreRewindPoint_PruneKeepsOlderPointsFromEarlierRuns` + drives two real runs, restores to run 2's edit point, then restores to + run 1's write point and asserts it still succeeds. diff --git a/docs/runbooks/session-rewind.md b/docs/runbooks/session-rewind.md index bfb94e51..ae6f9867 100644 --- a/docs/runbooks/session-rewind.md +++ b/docs/runbooks/session-rewind.md @@ -34,3 +34,5 @@ The confirmation token is required. Before confirming, ensure uncommitted work m Snapshots are captured before addressable `write`, `edit`, and `apply_patch` targets. Files over the per-file cap and points exceeding the per-conversation cap are listed as skipped and cannot be restored. Snapshot records are deleted automatically when their conversation is deleted or removed by retention. If restore returns an external-modification refusal, inspect or commit the current file first; use `force` only when losing that current content is intentional. Restoring an older point after a *later agent* edit to the same file needs no `force`: the expected hash for every earlier point sharing that path is kept current as the agent writes it, so `force` is only needed when the on-disk content actually diverges from the last agent-written state (issue #1371). + +Message truncation is keyed on the conversation-wide index of the assistant message that made the rewound tool call, not the tool-call step within its own run, so rewinding to a point from a later run in a multi-run conversation keeps every earlier run's messages and the chosen point's user prompt, deleting that assistant message and everything after it -- history never ends with an assistant message whose tool call has no response, which real providers reject on the next turn (issue #1370). Pruning of superseded rewind points uses the same conversation-wide boundary, so a point from an earlier, unrelated run is never deleted by a later run's restore. A rewind point captured before this fix has no recorded boundary and falls back to the old step-based truncation and pruning, logging a warning. A successful restore also invalidates the daemon's in-memory conversation history for that conversation, so `GET /messages` and the next run reflect the truncation immediately rather than only after a restart. diff --git a/internal/harness/conversation_store_sqlite.go b/internal/harness/conversation_store_sqlite.go index 4d7fdb27..967660bb 100644 --- a/internal/harness/conversation_store_sqlite.go +++ b/internal/harness/conversation_store_sqlite.go @@ -5,6 +5,7 @@ import ( "database/sql" "encoding/json" "fmt" + "log" "os" "path/filepath" "strings" @@ -204,6 +205,15 @@ func (s *SQLiteConversationStore) Migrate(ctx context.Context) error { } } + // Idempotent migration: add message_boundary column to rewind_points if it + // doesn't exist (issue #1370). Existing rows default to 0, which restore + // treats as "not recorded" and falls back to the legacy step comparison. + if !s.columnExists(ctx, "rewind_points", "message_boundary") { + if _, err := s.db.ExecContext(ctx, `ALTER TABLE rewind_points ADD COLUMN message_boundary INTEGER NOT NULL DEFAULT 0`); err != nil { + return fmt.Errorf("migrate add message_boundary column: %w", err) + } + } + // Idempotent migration: create FTS5 triggers if they don't exist. // Triggers keep conversation_messages_fts in sync with conversation_messages. triggers := []string{ @@ -559,7 +569,7 @@ func (s *SQLiteConversationStore) SaveRewindPoint(ctx context.Context, point Rew if _, err := tx.ExecContext(ctx, `INSERT OR IGNORE INTO conversations (id, created_at, updated_at) VALUES (?, ?, ?)`, point.ConversationID, created.Format(time.RFC3339Nano), created.Format(time.RFC3339Nano)); err != nil { return fmt.Errorf("create rewind conversation: %w", err) } - if _, err := tx.ExecContext(ctx, `INSERT INTO rewind_points (id, conversation_id, step, tool, created_at) VALUES (?, ?, ?, ?, ?)`, point.ID, point.ConversationID, point.Step, point.Tool, created.Format(time.RFC3339Nano)); err != nil { + if _, err := tx.ExecContext(ctx, `INSERT INTO rewind_points (id, conversation_id, step, tool, created_at, message_boundary) VALUES (?, ?, ?, ?, ?, ?)`, point.ID, point.ConversationID, point.Step, point.Tool, created.Format(time.RFC3339Nano), point.MessageBoundary); err != nil { return fmt.Errorf("insert rewind point: %w", err) } stmt, err := tx.PrepareContext(ctx, `INSERT INTO rewind_file_snapshots (point_id, path, content, existed, skipped, skip_reason, expected_hash) VALUES (?, ?, ?, ?, ?, ?, ?)`) @@ -655,7 +665,7 @@ func (s *SQLiteConversationStore) FinalizeRewindPoint(ctx context.Context, point // ListRewindPoints returns newest rewind points first with their captured files. func (s *SQLiteConversationStore) ListRewindPoints(ctx context.Context, convID string) ([]RewindPoint, error) { - rows, err := s.db.QueryContext(ctx, `SELECT p.id, p.step, p.tool, p.created_at, f.path, f.content, COALESCE(f.existed,0), COALESCE(f.skipped,0), COALESCE(f.skip_reason,''), COALESCE(f.expected_hash,'') FROM rewind_points p LEFT JOIN rewind_file_snapshots f ON f.point_id=p.id WHERE p.conversation_id=? ORDER BY p.step DESC, p.created_at DESC, f.id ASC`, convID) + rows, err := s.db.QueryContext(ctx, `SELECT p.id, p.step, p.tool, p.created_at, COALESCE(p.message_boundary,0), f.path, f.content, COALESCE(f.existed,0), COALESCE(f.skipped,0), COALESCE(f.skip_reason,''), COALESCE(f.expected_hash,'') FROM rewind_points p LEFT JOIN rewind_file_snapshots f ON f.point_id=p.id WHERE p.conversation_id=? ORDER BY p.step DESC, p.created_at DESC, f.id ASC`, convID) if err != nil { return nil, fmt.Errorf("list rewind points: %w", err) } @@ -665,9 +675,9 @@ func (s *SQLiteConversationStore) ListRewindPoints(ctx context.Context, convID s for rows.Next() { var id, tool, created, reason, expected string var path sql.NullString - var step, existed, skipped int + var step, messageBoundary, existed, skipped int var content []byte - if err := rows.Scan(&id, &step, &tool, &created, &path, &content, &existed, &skipped, &reason, &expected); err != nil { + if err := rows.Scan(&id, &step, &tool, &created, &messageBoundary, &path, &content, &existed, &skipped, &reason, &expected); err != nil { return nil, fmt.Errorf("scan rewind point: %w", err) } i, ok := byID[id] @@ -675,7 +685,7 @@ func (s *SQLiteConversationStore) ListRewindPoints(ctx context.Context, convID s t, _ := time.Parse(time.RFC3339Nano, created) i = len(points) byID[id] = i - points = append(points, RewindPoint{ID: id, ConversationID: convID, Step: step, Tool: tool, CreatedAt: t}) + points = append(points, RewindPoint{ID: id, ConversationID: convID, Step: step, Tool: tool, CreatedAt: t, MessageBoundary: messageBoundary}) } if path.Valid && path.String != "" { points[i].Files = append(points[i].Files, RewindFileSnapshot{Path: path.String, Content: content, Exists: existed == 1, Skipped: skipped == 1, SkipReason: reason, ExpectedHash: expected}) @@ -757,13 +767,43 @@ func (s *SQLiteConversationStore) RestoreRewindPoint(ctx context.Context, convID return result, fmt.Errorf("rewind begin tx: %w", err) } defer tx.Rollback() - res, err := tx.ExecContext(ctx, `DELETE FROM conversation_messages WHERE conversation_id=? AND step>?`, convID, point.Step) + // point.Step is a run-local tool-call counter (see runner_step_engine.go), + // not comparable to conversation_messages.step, which is a + // conversation-wide message index shared across every run on this + // conversation (issue #1370). point.MessageBoundary records that + // conversation-wide index at capture time and is the only field safe to + // truncate against. Points captured before this field existed have + // MessageBoundary==0 ("not recorded"); rather than silently deleting + // everything, fall back to the legacy (imperfect, multi-run-unsafe) + // step comparison and log a warning so operators can see it happened. + var res sql.Result + if point.MessageBoundary > 0 { + res, err = tx.ExecContext(ctx, `DELETE FROM conversation_messages WHERE conversation_id=? AND step>=?`, convID, point.MessageBoundary) + } else { + log.Printf("rewind: point %q (conversation %q) has no recorded message boundary; falling back to step-based truncation, which can delete unrelated messages in a multi-run conversation", point.ID, convID) + res, err = tx.ExecContext(ctx, `DELETE FROM conversation_messages WHERE conversation_id=? AND step>?`, convID, point.Step) + } if err != nil { return result, fmt.Errorf("rewind truncate messages: %w", err) } n, _ := res.RowsAffected() result.MessagesTruncated = int(n) - if _, err := tx.ExecContext(ctx, `DELETE FROM rewind_points WHERE conversation_id=? AND (step>? OR (step=? AND id<>?))`, convID, point.Step, point.Step, point.ID); err != nil { + // point.Step is run-local and restarts every run, so it collides across + // runs (run 2's first mutating call and run 1's first mutating call are + // both step 0/1 within their own run but capture entirely unrelated + // points): pruning by it deleted an older, still-valid point from an + // earlier run whenever a later run's point happened to share a step + // number. Prune by MessageBoundary instead when it is recorded: a point + // is superseded only if it comes after the target in conversation order + // (a strictly greater boundary), or shares the same boundary (parallel + // tool calls in one assistant turn) but was captured later. The target + // itself is always excluded. Fall back to the legacy step predicate only + // when the target has no recorded boundary. + if point.MessageBoundary > 0 { + if _, err := tx.ExecContext(ctx, `DELETE FROM rewind_points WHERE conversation_id=? AND id<>? AND (message_boundary>? OR (message_boundary=? AND created_at>?))`, convID, point.ID, point.MessageBoundary, point.MessageBoundary, point.CreatedAt.Format(time.RFC3339Nano)); err != nil { + return result, fmt.Errorf("rewind delete future points: %w", err) + } + } else if _, err := tx.ExecContext(ctx, `DELETE FROM rewind_points WHERE conversation_id=? AND (step>? OR (step=? AND id<>?))`, convID, point.Step, point.Step, point.ID); err != nil { return result, fmt.Errorf("rewind delete future points: %w", err) } // The files just restored now hold this content on disk, so every diff --git a/internal/harness/rewind.go b/internal/harness/rewind.go index 02a02481..958547a1 100644 --- a/internal/harness/rewind.go +++ b/internal/harness/rewind.go @@ -73,6 +73,14 @@ type RewindPoint struct { Tool string `json:"tool"` CreatedAt time.Time `json:"created_at"` Files []RewindFileSnapshot `json:"files"` + // MessageBoundary is the conversation-wide message count captured at the + // moment this point was recorded (the number of conversation_messages + // rows that must survive a restore). Step is a run-local tool-call + // counter and is NOT comparable to conversation_messages.step across + // runs (issue #1370); MessageBoundary is. Zero means "not recorded" + // (points captured before this field existed), in which case restore + // falls back to the legacy step-based comparison. + MessageBoundary int `json:"message_boundary,omitempty"` } // RewindStore is deliberately optional so existing ConversationStore adapters diff --git a/internal/harness/rewind_store_test.go b/internal/harness/rewind_store_test.go index f08efa77..7963aa2c 100644 --- a/internal/harness/rewind_store_test.go +++ b/internal/harness/rewind_store_test.go @@ -1,9 +1,12 @@ package harness import ( + "bytes" "context" + "log" "os" "path/filepath" + "strings" "testing" ) @@ -384,6 +387,125 @@ func TestConversationSnapshotCapSkipsAdditionalContent(t *testing.T) { } } +// TestRestoreRewindPoint_MultiRunTruncatesOnlyAfterPoint reproduces issue +// #1370: rewinding to a point captured during a conversation's second run +// must keep every message from the first run plus the second run's user +// prompt, deleting the tool-call message this point precedes and everything +// after it. The point's Step field is a run-local tool-call counter (run2's +// first mutating call is step 0 within run2), which is not comparable to +// conversation_messages.step (a conversation-wide index) -- comparing them +// directly deletes run 1's messages too. +// +// MessageBoundary is the index of the assistant message carrying the +// rewound tool call, not the index just after it: restoring must delete +// that assistant message too, not just its tool result, otherwise the +// persisted history ends with an assistant message whose tool_calls have no +// tool-result messages, which real providers (e.g. OpenAI) reject on the +// next turn even though the fake/stub providers used in tests do not. +func TestRestoreRewindPoint_MultiRunTruncatesOnlyAfterPoint(t *testing.T) { + ctx := context.Background() + store := newTestConversationStore(t) + convID := "multi-run-conv" + + // Final persisted state after both runs completed: run 1 (4 messages) + // followed by run 2 (4 messages). Steps are the conversation-wide index + // 0..7, matching what SaveConversationWithCost writes at each run's + // completion. + all := []Message{ + {Role: "user", Content: "run1: write a.txt"}, + {Role: "assistant", Content: "", ToolCalls: []ToolCall{{ID: "c1", Name: "write"}}}, + {Role: "tool", Name: "write", ToolCallID: "c1", Content: "written"}, + {Role: "assistant", Content: "run1 done"}, + {Role: "user", Content: "run2: edit a.txt"}, + {Role: "assistant", Content: "", ToolCalls: []ToolCall{{ID: "c2", Name: "edit"}}}, + {Role: "tool", Name: "edit", ToolCallID: "c2", Content: "edited"}, + {Role: "assistant", Content: "run2 done"}, + } + + // The rewind point is captured mid-run-2, immediately before the "edit" + // tool executes. The conversation holds 4 run-1 messages, run2's user + // prompt at index 4, and run2's assistant tool-call message at index 5: + // a message boundary of 5 (the tool-call message's own index). + point := RewindPoint{ID: "run2-edit", ConversationID: convID, Step: 0, Tool: "edit", MessageBoundary: 5} + if err := store.SaveRewindPoint(ctx, point); err != nil { + t.Fatalf("SaveRewindPoint: %v", err) + } + + // Run 2 completes and overwrites the full conversation-wide history, as + // Runner.completeRun does via SaveConversationWithCost. + if err := store.SaveConversation(ctx, convID, all); err != nil { + t.Fatalf("SaveConversation: %v", err) + } + + result, err := store.RestoreRewindPoint(ctx, convID, "run2-edit", t.TempDir(), true) + if err != nil { + t.Fatalf("RestoreRewindPoint: %v", err) + } + if result.MessagesTruncated != 3 { + t.Errorf("MessagesTruncated = %d, want 3 (run2's tool-call message, tool result, and final answer)", result.MessagesTruncated) + } + got, err := store.LoadMessages(ctx, convID) + if err != nil { + t.Fatalf("LoadMessages: %v", err) + } + if len(got) != 5 { + t.Fatalf("LoadMessages returned %d messages, want 5 (run1's 4 plus run2's user prompt): %#v", len(got), got) + } + for i, want := range all[:5] { + if got[i].Content != want.Content || got[i].Role != want.Role { + t.Errorf("message[%d] = %+v, want %+v", i, got[i], want) + } + } + if got[3].Content != "run1 done" { + t.Fatalf("run 1's final answer was truncated; got[3]=%+v", got[3]) + } + last := got[len(got)-1] + if last.Role == "assistant" && len(last.ToolCalls) > 0 { + t.Fatalf("restore left a dangling assistant message with tool_calls as the last persisted message: %+v", last) + } +} + +// TestRestoreRewindPoint_FallsBackWhenBoundaryUnset proves that points saved +// before MessageBoundary existed (or by any caller that never sets it) do not +// silently over-delete: restore falls back to the legacy step comparison +// (documented, if imperfect) and logs a warning rather than deleting +// everything at step>=0. +func TestRestoreRewindPoint_FallsBackWhenBoundaryUnset(t *testing.T) { + ctx := context.Background() + store := newTestConversationStore(t) + convID := "legacy-point-conv" + if err := store.SaveConversation(ctx, convID, []Message{ + {Role: "user", Content: "keep"}, + {Role: "assistant", Content: "drop"}, + }); err != nil { + t.Fatal(err) + } + // No MessageBoundary set: zero value, matching every rewind point + // captured before this field existed. + if err := store.SaveRewindPoint(ctx, RewindPoint{ID: "legacy", ConversationID: convID, Step: 0, Tool: "write"}); err != nil { + t.Fatal(err) + } + + var buf bytes.Buffer + log.SetOutput(&buf) + t.Cleanup(func() { log.SetOutput(os.Stderr) }) + + result, err := store.RestoreRewindPoint(ctx, convID, "legacy", t.TempDir(), true) + if err != nil { + t.Fatalf("RestoreRewindPoint: %v", err) + } + if result.MessagesTruncated != 1 { + t.Fatalf("MessagesTruncated = %d, want 1 (legacy step-based fallback keeps step<=0)", result.MessagesTruncated) + } + got, err := store.LoadMessages(ctx, convID) + if err != nil || len(got) != 1 || got[0].Content != "keep" { + t.Fatalf("LoadMessages = %#v, err=%v, want [keep]", got, err) + } + if !strings.Contains(buf.String(), "legacy") { + t.Fatalf("expected a logged warning naming the point falling back to step-based truncation, got: %q", buf.String()) + } +} + func TestExtractRewindPathsUsesWriteEditAndPatchArguments(t *testing.T) { paths := ExtractRewindPaths("apply_patch", []byte(`{"patch":"--- a/a.txt\n+++ b/a.txt\n--- a/b.txt\n+++ b/b.txt"}`)) if len(paths) != 2 || paths[0] != "a.txt" || paths[1] != "b.txt" { diff --git a/internal/harness/runner.go b/internal/harness/runner.go index b6b2499c..ad9c61a4 100644 --- a/internal/harness/runner.go +++ b/internal/harness/runner.go @@ -5686,6 +5686,28 @@ func (r *Runner) conversationID(runID string) string { return state.run.ConversationID } +// InvalidateConversationHistory drops the in-memory conversation mirror for +// conversationID so the next read (ConversationMessages, +// ConversationMessagesSnapshot, or the next run's loadConversationHistory) +// falls through to the durable store instead of the write-behind cache +// populated at each run's completion. The mirror is never itself truncated +// by a rewind's DB-level restore, so without this call a rewound +// conversation kept serving (and the next run kept re-persisting) messages +// the store had already deleted (issue #1370). Callers making an external +// mutation to conversation_messages outside the normal run lifecycle (only +// rewind today) must call this after the mutation succeeds. +func (r *Runner) InvalidateConversationHistory(conversationID string) { + conversationID = strings.TrimSpace(conversationID) + if conversationID == "" { + return + } + r.mu.Lock() + delete(r.conversations, conversationID) + delete(r.conversationTouched, conversationID) + delete(r.conversationMessageWatermarks, conversationID) + r.mu.Unlock() +} + func (r *Runner) ConversationMessages(conversationID string) ([]Message, bool) { rc := r.snapshotConfig() r.mu.RLock() diff --git a/internal/harness/runner_step_engine.go b/internal/harness/runner_step_engine.go index bb210437..4551fa7c 100644 --- a/internal/harness/runner_step_engine.go +++ b/internal/harness/runner_step_engine.go @@ -733,6 +733,14 @@ func (se *stepEngine) run() { ToolCalls: append([]ToolCall(nil), result.ToolCalls...), Reasoning: capturedReasoning, }) + // The conversation-wide index of the assistant message just appended. + // A rewind restore must delete this message and everything after it, + // not just its tool result: leaving it as the last persisted message + // dangles tool_calls with no tool-result response, which real + // providers reject on the next turn (issue #1370 follow-up). Every + // tool call in this turn -- including parallel calls sharing one + // assistant message -- captures the same index below. + assistantToolCallIndex := len(messages) - 1 r.stepSetMessages(runID, messages) r.snapshotRecordMessage(runID, "assistant", result.Content) @@ -1349,7 +1357,16 @@ func (se *stepEngine) run() { if err := metaStore.EnsureConversationMeta(pe.toolCtx, meta.ConversationID, workspace, tenantID); err != nil { r.emit(runID, EventToolCallCompleted, map[string]any{"call_id": pe.call.ID, "tool": pe.call.Name, "rewind_warning": err.Error()}) } else { - point := RewindPoint{ID: fmt.Sprintf("%s-%d-%s", runID, step, pe.call.ID), ConversationID: meta.ConversationID, Step: step, Tool: pe.call.Name} + // MessageBoundary is the conversation-wide index of the + // assistant message carrying this tool call (assistantToolCallIndex, + // captured just above). A restore must delete that message + // and everything after it -- unlike Step, which only counts + // tool calls within this run and is meaningless across runs + // (issue #1370), and unlike len(messages), which would keep + // the assistant message dangling with no tool-result response + // (issue #1370 follow-up). Parallel tool calls issued in this + // same assistant turn all capture this same index. + point := RewindPoint{ID: fmt.Sprintf("%s-%d-%s", runID, step, pe.call.ID), ConversationID: meta.ConversationID, Step: step, Tool: pe.call.Name, MessageBoundary: assistantToolCallIndex} if err := CaptureRewindPreImage(pe.toolCtx, rewind, point, workspace, pe.callArgs); err != nil { r.emit(runID, EventToolCallCompleted, map[string]any{"call_id": pe.call.ID, "tool": pe.call.Name, "rewind_warning": err.Error()}) } diff --git a/internal/harness/runner_test.go b/internal/harness/runner_test.go index c57dfbef..09e7bd2c 100644 --- a/internal/harness/runner_test.go +++ b/internal/harness/runner_test.go @@ -308,6 +308,296 @@ func TestIssue1256_PersistsTrustedWorkspaceBeforeMutatingRewindCapture(t *testin } } +// TestRewindThenNextRunDoesNotResurrectTruncatedMessages is a regression test +// for the third symptom in issue #1370's live reproduction: after a rewind, +// the *next* run's LLM context must not contain the messages that were just +// truncated. Before the fix, the runner's in-memory conversation mirror +// (populated at each run's completion) was never invalidated by rewind, so +// the next run's loadConversationHistory kept reading the stale mirror and +// resurrected the truncated messages into a fresh CompletionRequest -- which +// then got re-persisted over the store's truncation. This test exercises a +// different observation point than the store-level and HTTP-level tests: the +// actual provider request payload for the run that follows a rewind. +func TestRewindThenNextRunDoesNotResurrectTruncatedMessages(t *testing.T) { + workspace := t.TempDir() + registry := NewRegistry() + writeFile := func(_ context.Context, raw json.RawMessage) (string, error) { + var args struct { + Path string `json:"path"` + Content string `json:"content"` + } + if err := json.Unmarshal(raw, &args); err != nil { + return "", err + } + return "ok", os.WriteFile(filepath.Join(workspace, args.Path), []byte(args.Content), 0o600) + } + for _, name := range []string{"write", "edit"} { + if err := registry.Register(ToolDefinition{Name: name, Mutating: true, Parameters: map[string]any{"type": "object"}}, writeFile); err != nil { + t.Fatalf("register %s: %v", name, err) + } + } + + store := newTestConversationStore(t) + provider := &capturingProvider{turns: []CompletionResult{ + {ToolCalls: []ToolCall{{ID: "c1", Name: "write", Arguments: `{"path":"a.txt","content":"v1"}`}}}, + {Content: "run1 done"}, + {ToolCalls: []ToolCall{{ID: "c2", Name: "edit", Arguments: `{"path":"a.txt","content":"v2"}`}}}, + {Content: "run2 done"}, + {Content: "run3 done"}, + }} + runner := NewRunner(provider, registry, RunnerConfig{ + DefaultModel: "test", + MaxSteps: 20, + ConversationStore: store, + WorkspaceBaseOptions: WorkspaceProvisionOptions{RepoPath: workspace}, + }) + convID := "rewind-resurrect-conv" + + run1, err := runner.StartRun(RunRequest{Prompt: "write a.txt", ConversationID: convID}) + if err != nil { + t.Fatalf("StartRun run1: %v", err) + } + waitForRunCompletion(t, runner, run1.ID) + + run2, err := runner.StartRun(RunRequest{Prompt: "edit a.txt", ConversationID: convID}) + if err != nil { + t.Fatalf("StartRun run2: %v", err) + } + waitForRunCompletion(t, runner, run2.ID) + + points, err := store.ListRewindPoints(context.Background(), convID) + if err != nil { + t.Fatalf("ListRewindPoints: %v", err) + } + var editPointID string + for _, p := range points { + if p.Tool == "edit" { + editPointID = p.ID + } + } + if editPointID == "" { + t.Fatalf("no rewind point captured for the edit tool call: %#v", points) + } + + restoreResult, err := store.RestoreRewindPoint(context.Background(), convID, editPointID, workspace, true) + if err != nil { + t.Fatalf("RestoreRewindPoint: %v", err) + } + if restoreResult.MessagesTruncated != 3 { + t.Fatalf("MessagesTruncated = %d, want 3 (run2's tool-call message, tool result, and final answer)", restoreResult.MessagesTruncated) + } + // This is the seam the HTTP handler calls after a successful restore. + // Omitting it reproduces the resurrection bug even though the store is + // correctly truncated. + runner.InvalidateConversationHistory(convID) + + run3, err := runner.StartRun(RunRequest{Prompt: "what happened?", ConversationID: convID}) + if err != nil { + t.Fatalf("StartRun run3: %v", err) + } + waitForRunCompletion(t, runner, run3.ID) + + provider.mu.Lock() + lastReq := provider.calls[len(provider.calls)-1] + provider.mu.Unlock() + for _, m := range lastReq.Messages { + if strings.Contains(m.Content, "run2 done") { + t.Fatalf("run3's context resurrected run2's truncated final answer: %#v", lastReq.Messages) + } + if m.ToolCallID == "c2" { + t.Fatalf("run3's context resurrected run2's truncated tool result: %#v", lastReq.Messages) + } + } +} + +// TestRestoreRewindPoint_NeverLeavesDanglingToolCall is a follow-up +// regression on PR #1389: the original boundary kept the assistant message +// that carries the rewound tool call, so a restore could leave persisted +// history ending in an assistant message whose tool_calls have no +// corresponding tool-result messages. Real providers reject that shape +// (OpenAI: "An assistant message with 'tool_calls' must be followed by tool +// messages responding to each tool_call_id"); the fake/stub providers used +// elsewhere in this suite do not enforce it, which is why that bug shipped +// with green tests. MessageBoundary must be the index of the assistant +// message carrying the rewound tool call itself, so restoring deletes that +// message and everything after it. For two tool calls issued in one +// assistant turn (parallel, non-parallel-safe mutating tools execute +// sequentially but originate from one assistant message), both calls' points +// must share that same boundary. +func TestRestoreRewindPoint_NeverLeavesDanglingToolCall(t *testing.T) { + workspace := t.TempDir() + registry := NewRegistry() + writeFile := func(_ context.Context, raw json.RawMessage) (string, error) { + var args struct { + Path string `json:"path"` + Content string `json:"content"` + } + if err := json.Unmarshal(raw, &args); err != nil { + return "", err + } + return "ok", os.WriteFile(filepath.Join(workspace, args.Path), []byte(args.Content), 0o600) + } + for _, name := range []string{"write", "edit"} { + if err := registry.Register(ToolDefinition{Name: name, Mutating: true, Parameters: map[string]any{"type": "object"}}, writeFile); err != nil { + t.Fatalf("register %s: %v", name, err) + } + } + + store := newTestConversationStore(t) + // One assistant turn issues two tool calls (neither tool is registered + // parallel-safe, so the step engine executes them sequentially but they + // still originate from a single assistant message). + provider := &stubProvider{turns: []CompletionResult{ + {ToolCalls: []ToolCall{ + {ID: "pa1", Name: "write", Arguments: `{"path":"a.txt","content":"v1"}`}, + {ID: "pa2", Name: "edit", Arguments: `{"path":"b.txt","content":"v2"}`}, + }}, + {Content: "done"}, + }} + runner := NewRunner(provider, registry, RunnerConfig{ + DefaultModel: "test", + MaxSteps: 20, + ConversationStore: store, + WorkspaceBaseOptions: WorkspaceProvisionOptions{RepoPath: workspace}, + }) + convID := "parallel-rewind-conv" + run, err := runner.StartRun(RunRequest{Prompt: "write and edit", ConversationID: convID}) + if err != nil { + t.Fatalf("StartRun: %v", err) + } + waitForRunCompletion(t, runner, run.ID) + + points, err := store.ListRewindPoints(context.Background(), convID) + if err != nil { + t.Fatalf("ListRewindPoints: %v", err) + } + if len(points) != 2 { + t.Fatalf("points = %#v, want 2 (one per parallel tool call)", points) + } + if points[0].MessageBoundary != points[1].MessageBoundary { + t.Fatalf("parallel tool calls in one assistant turn have different boundaries: %+v vs %+v", points[0], points[1]) + } + + // Restore using either point should truncate at the assistant message + // itself, not just the tool call that point happens to name. + if _, err := store.RestoreRewindPoint(context.Background(), convID, points[0].ID, workspace, true); err != nil { + t.Fatalf("RestoreRewindPoint: %v", err) + } + + got, err := store.LoadMessages(context.Background(), convID) + if err != nil { + t.Fatalf("LoadMessages: %v", err) + } + if len(got) == 0 { + t.Fatalf("LoadMessages returned no messages; want at least the user prompt") + } + last := got[len(got)-1] + if last.Role == "assistant" && len(last.ToolCalls) > 0 { + t.Fatalf("restore left a dangling assistant message with tool_calls as the last persisted message: %+v", last) + } + assistantCallIDs := map[string]bool{} + for _, m := range got { + if m.Role == "assistant" { + for _, tc := range m.ToolCalls { + assistantCallIDs[tc.ID] = true + } + } + } + for _, m := range got { + if m.Role == "tool" && !assistantCallIDs[m.ToolCallID] { + t.Fatalf("tool message %+v has no preceding assistant tool_calls entry for its ID; a real provider would reject this history", m) + } + } +} + +// TestRestoreRewindPoint_PruneKeepsOlderPointsFromEarlierRuns is a regression +// found by live verification on main after #1378 merged: RestoreRewindPoint's +// future-point pruning query (`DELETE FROM rewind_points WHERE ... step>? OR +// (step=? AND id<>?)`) compared point.Step, the same run-local tool-call +// counter whose message-truncation misuse issue #1370 already fixed. Step is +// reused per run (run 2's edit point is step 1 within run 2, run 1's write +// point is also step 1 within run 1 -- an entirely unrelated run), so +// restoring the edit point deleted the write point too, and a later restore +// to that still-valid older point returned "not found" even though it was +// never superseded. +func TestRestoreRewindPoint_PruneKeepsOlderPointsFromEarlierRuns(t *testing.T) { + workspace := t.TempDir() + registry := NewRegistry() + writeFile := func(_ context.Context, raw json.RawMessage) (string, error) { + var args struct { + Path string `json:"path"` + Content string `json:"content"` + } + if err := json.Unmarshal(raw, &args); err != nil { + return "", err + } + return "ok", os.WriteFile(filepath.Join(workspace, args.Path), []byte(args.Content), 0o600) + } + for _, name := range []string{"write", "edit"} { + if err := registry.Register(ToolDefinition{Name: name, Mutating: true, Parameters: map[string]any{"type": "object"}}, writeFile); err != nil { + t.Fatalf("register %s: %v", name, err) + } + } + + store := newTestConversationStore(t) + provider := &stubProvider{turns: []CompletionResult{ + {ToolCalls: []ToolCall{{ID: "c1", Name: "write", Arguments: `{"path":"a.txt","content":"v1"}`}}}, + {Content: "run1 done"}, + {ToolCalls: []ToolCall{{ID: "c2", Name: "edit", Arguments: `{"path":"a.txt","content":"v2"}`}}}, + {Content: "run2 done"}, + }} + runner := NewRunner(provider, registry, RunnerConfig{ + DefaultModel: "test", + MaxSteps: 20, + ConversationStore: store, + WorkspaceBaseOptions: WorkspaceProvisionOptions{RepoPath: workspace}, + }) + convID := "prune-older-point-conv" + + run1, err := runner.StartRun(RunRequest{Prompt: "write a.txt", ConversationID: convID}) + if err != nil { + t.Fatalf("StartRun run1: %v", err) + } + waitForRunCompletion(t, runner, run1.ID) + + run2, err := runner.StartRun(RunRequest{Prompt: "edit a.txt", ConversationID: convID}) + if err != nil { + t.Fatalf("StartRun run2: %v", err) + } + waitForRunCompletion(t, runner, run2.ID) + + points, err := store.ListRewindPoints(context.Background(), convID) + if err != nil { + t.Fatalf("ListRewindPoints: %v", err) + } + var writePointID, editPointID string + for _, p := range points { + switch p.Tool { + case "write": + writePointID = p.ID + case "edit": + editPointID = p.ID + } + } + if writePointID == "" || editPointID == "" { + t.Fatalf("expected one rewind point per tool call: %#v", points) + } + + if _, err := store.RestoreRewindPoint(context.Background(), convID, editPointID, workspace, true); err != nil { + t.Fatalf("RestoreRewindPoint(edit): %v", err) + } + + // The older write-point, captured in an earlier and entirely unrelated + // run, must survive the edit-point restore's pruning: it was never + // superseded by anything, and this restore must still be possible. + if _, err := store.RestoreRewindPoint(context.Background(), convID, writePointID, workspace, true); err != nil { + t.Fatalf("RestoreRewindPoint(write) after an unrelated later-run restore: %v", err) + } + if _, statErr := os.Stat(filepath.Join(workspace, "a.txt")); !os.IsNotExist(statErr) { + t.Fatalf("a.txt still exists after restoring to the write point (its pre-image was absent): stat err=%v", statErr) + } +} + func TestRunnerInjectsMemorySnippetAndEmitsMemoryEvents(t *testing.T) { t.Parallel() diff --git a/internal/server/http_conversations.go b/internal/server/http_conversations.go index 908ddd7c..7dfb3daa 100644 --- a/internal/server/http_conversations.go +++ b/internal/server/http_conversations.go @@ -428,6 +428,13 @@ func (s *Server) handleRestoreRewind(w http.ResponseWriter, r *http.Request, con writeError(w, code, "rewind_refused", err.Error()) return } + // The restore above truncates conversation_messages in the store, but the + // runner's in-memory conversation mirror (populated at each run's + // completion) is a separate write-behind cache that the store mutation + // never touches. Without invalidating it here, /messages and the next + // run's context keep serving the pre-rewind history until a daemon + // restart forces a reload from the (now-truncated) store (issue #1370). + s.runner.InvalidateConversationHistory(convID) writeJSON(w, http.StatusOK, result) } diff --git a/internal/server/http_rewind_test.go b/internal/server/http_rewind_test.go index 2bdd4d55..b1a3789b 100644 --- a/internal/server/http_rewind_test.go +++ b/internal/server/http_rewind_test.go @@ -4,11 +4,13 @@ import ( "bytes" "context" "encoding/json" + "go-agent-harness/internal/fakeprovider" "go-agent-harness/internal/harness" "net/http" "net/http/httptest" "os" "path/filepath" + "strings" "testing" ) @@ -224,3 +226,147 @@ func TestRestoreRewindEndpointRefusesExternalModificationWithoutForce(t *testing t.Fatalf("force restore status=%d body=%s, want 200", rr2.Code, rr2.Body.String()) } } + +// TestRestoreRewindEndpoint_MultiRunKeepsPriorMessagesAndInvalidatesLiveMirror +// reproduces issue #1370's exact repro: two completed runs on one +// conversation (run 1 writes a.txt, run 2 edits it), then a rewind to run +// 2's first tool call. It proves both halves of the fix through the real +// HTTP handler: (1) the DB truncation keeps run 1's messages plus run 2's +// user prompt, deleting run 2's tool-call message and everything after it +// (not just its tool result -- leaving the tool-call message dangling with +// no tool-result response is a shape real providers reject), and (2) GET +// /messages reflects that truncation immediately afterward instead of +// continuing to serve the runner's stale in-memory mirror (which, before +// the fix, resurrects the deleted messages until a daemon restart). +func TestRestoreRewindEndpoint_MultiRunKeepsPriorMessagesAndInvalidatesLiveMirror(t *testing.T) { + store := newTestSQLiteStore(t) + workspace := t.TempDir() + if err := os.WriteFile(filepath.Join(workspace, "a.txt"), []byte("v0"), 0o600); err != nil { + t.Fatal(err) + } + + registry := harness.NewRegistry() + writeFile := func(_ context.Context, raw json.RawMessage) (string, error) { + var args struct { + Path string `json:"path"` + Content string `json:"content"` + } + if err := json.Unmarshal(raw, &args); err != nil { + return "", err + } + if err := os.WriteFile(filepath.Join(workspace, args.Path), []byte(args.Content), 0o600); err != nil { + return "", err + } + return "ok", nil + } + for _, name := range []string{"write", "edit"} { + if err := registry.Register(harness.ToolDefinition{ + Name: name, + Mutating: true, + Parameters: map[string]any{"type": "object"}, + }, writeFile); err != nil { + t.Fatalf("register %s: %v", name, err) + } + } + + prov := fakeprovider.New([]fakeprovider.Turn{ + {ToolCalls: []harness.ToolCall{{ID: "c1", Name: "write", Arguments: `{"path":"a.txt","content":"v1"}`}}}, + {Content: "run1 done"}, + {ToolCalls: []harness.ToolCall{{ID: "c2", Name: "edit", Arguments: `{"path":"a.txt","content":"v2"}`}}}, + {Content: "run2 done"}, + }) + + runner := harness.NewRunner(prov, registry, harness.RunnerConfig{ + DefaultModel: "test", + MaxSteps: 20, + ConversationStore: store, + WorkspaceBaseOptions: harness.WorkspaceProvisionOptions{RepoPath: workspace}, + }) + handler := New(runner) + convID := "rewind-mirror-conv" + + run1, err := runner.StartRun(harness.RunRequest{Prompt: "write a.txt", ConversationID: convID}) + if err != nil { + t.Fatalf("StartRun run1: %v", err) + } + pollUntilRunTerminal(t, runner, run1.ID) + + run2, err := runner.StartRun(harness.RunRequest{Prompt: "edit a.txt", ConversationID: convID}) + if err != nil { + t.Fatalf("StartRun run2: %v", err) + } + pollUntilRunTerminal(t, runner, run2.ID) + + getMessages := func() []harness.Message { + t.Helper() + rr := httptest.NewRecorder() + handler.ServeHTTP(rr, httptest.NewRequest(http.MethodGet, "/v1/conversations/"+convID+"/messages", nil)) + if rr.Code != http.StatusOK { + t.Fatalf("GET /messages status=%d body=%s", rr.Code, rr.Body.String()) + } + var decoded struct { + Messages []harness.Message `json:"messages"` + } + if err := json.Unmarshal(rr.Body.Bytes(), &decoded); err != nil { + t.Fatalf("decode /messages: %v body=%s", err, rr.Body.String()) + } + return decoded.Messages + } + + before := getMessages() + if len(before) != 8 { + t.Fatalf("before rewind: got %d messages, want 8 (both runs' full history): %#v", len(before), before) + } + + rrPoints := httptest.NewRecorder() + handler.ServeHTTP(rrPoints, httptest.NewRequest(http.MethodGet, "/v1/conversations/"+convID+"/rewind-points", nil)) + if rrPoints.Code != http.StatusOK { + t.Fatalf("GET rewind-points status=%d body=%s", rrPoints.Code, rrPoints.Body.String()) + } + var listed struct { + Points []harness.RewindPoint `json:"points"` + } + if err := json.Unmarshal(rrPoints.Body.Bytes(), &listed); err != nil { + t.Fatalf("decode rewind-points: %v", err) + } + var editPointID string + for _, p := range listed.Points { + if p.Tool == "edit" { + editPointID = p.ID + } + } + if editPointID == "" { + t.Fatalf("no rewind point captured for the edit tool call: %#v", listed.Points) + } + + body, _ := json.Marshal(map[string]any{"point_id": editPointID}) + rr := httptest.NewRecorder() + handler.ServeHTTP(rr, httptest.NewRequest(http.MethodPost, "/v1/conversations/"+convID+"/rewind", bytes.NewReader(body))) + if rr.Code != http.StatusOK { + t.Fatalf("POST rewind status=%d body=%s", rr.Code, rr.Body.String()) + } + var result harness.RewindRestoreResult + if err := json.Unmarshal(rr.Body.Bytes(), &result); err != nil { + t.Fatalf("decode rewind result: %v", err) + } + if result.MessagesTruncated != 3 { + t.Errorf("MessagesTruncated = %d, want 3 (run2's tool-call message, tool result, and final answer)", result.MessagesTruncated) + } + + after := getMessages() + if len(after) != 5 { + t.Fatalf("after rewind: got %d messages, want 5 (run1's 4 plus run2's user prompt): %#v", len(after), after) + } + for _, m := range after { + if strings.Contains(m.Content, "run2 done") { + t.Fatalf("GET /messages still serves run2's truncated final answer after rewind (stale in-memory mirror): %#v", after) + } + } + if after[3].Content != "run1 done" { + t.Fatalf("run1's final answer was truncated; after[3]=%+v", after[3]) + } + last := after[len(after)-1] + if last.Role == "assistant" && len(last.ToolCalls) > 0 { + t.Fatalf("restore left a dangling assistant message with tool_calls as the last persisted message: %+v", last) + } +}