diff --git a/CLAUDE.md b/CLAUDE.md index edc9391e6..74939fae1 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -84,7 +84,7 @@ REST API at `/api/v1/`. Key endpoints: - `GET/PATCH/DELETE /workspaces/{ws}/items/{slug}` — item by slug - **Write responses (create/update) may carry `warnings.undeclared_fields`** (BUG-2850) — field keys stored in the item's `fields` blob that the collection's schema does not declare. They are ACCEPTED, not refused: a census found 168 live values under 14 such keys, and refusing them would break read-modify-write on items nobody edited wrongly. The element is additive and `omitempty`, so a clean write is byte-identical to before; system-written metadata (`implementation_notes`, `decision_log`, `github_pr`, `convention`) is excluded. The CLI prints the same list to **stderr**, never stdout, so `--format json` stays parseable - **Write responses may also carry `warnings.content_outcome`** (BUG-2995) — on a 200 it takes exactly one value, `applied_pending_flush`: the content went to the live collaborative document (a browser tab has the item open) rather than to `items.content`. It describes the WRITE, not the row's state at response time — a concurrent flush may already have updated the row, and the server does not re-read to find out. The response's `content` is then the markdown as **sent**, not as stored, and a read before a later `?source=collab-snapshot` flush lands answers with the PREVIOUS content — the lag, not a failed write. The stored form may also differ from the sent form: the markdown round-trips through the editor, so bullet markers, emphasis characters, list numbering and blank-line runs normalise, while already-canonical markdown survives unchanged (measured — `web/src/lib/collab/bug2995Roundtrip.svelte.test.ts`). No duration is claimed anywhere, and the flush is NOT guaranteed to happen at all (BUG-3000). The CLI prints this to **stderr**, like the other write warnings, and since TASK-3132 the LAST line of `pad item update`'s stdout also names it (`— body sent to the open editor … a following "pad item show" will return the OLD body`), so it survives `| tail -1` and a discarded stderr; that last line reads `body replaced, A → B bytes` / `body cleared` on every other content write - - **READ responses may carry `content_state`** (BUG-3000 / BUG-3033) — the read-side counterpart to `warnings.content_outcome` above, and it takes the same one value, `applied_pending_flush`. A write warning says what a REQUEST did; this says what the ROW is: the item's op-log holds CONTENT-BEARING updates above `items.content_flushed_op_log_id`, so the body being served is BEHIND the live collaborative document. Since BUG-3124 rows that provably cannot change the document — y-protocols SyncStep1 frames, empty updates, and byte-identical re-sends of an earlier row — are persisted but marked `content_bearing = false` and not counted; they used to keep an item "pending" forever after its tab closed (measured: 470 pending items → 189 on the live DB). The classifier is envelope-only (no Yjs parse) and strict: a frame that does not parse exactly stays content-bearing. Additive and `omitempty`, and emitted only where a real body is — a summary or metadata projection that serves no content never claims its absent body is stale. The window is **unbounded**: nothing server-side moves that content into `items.content` (the op-log GC's flush-coverage guard deliberately RETAINS unflushed rows rather than flushing them), so the row catches up only when a browser tab next opens the item, which may never happen. Opening it is now enough even when nothing needs flushing (BUG-3124 unit B): a caught-up tab whose document still renders to the stored body calls `POST /workspaces/{ws}/items/{slug}/collab-watermark {op_log_cursor, content_sha256}`, and the server advances the flush watermark iff `cursor == MAX(op-log id)` and the sha256 matches `items.content`, atomically, writing no content, version, `seq` or `updated_at` — before this, a view that changed nothing was deduped and left the item "pending" forever. Web-client only; no CLI/MCP surface. The content is not lost — the op-log is the durability layer — but the marker is a signal to RE-READ LATER, never to re-send. The predicate is broader than "an API write is pending flush" and deliberately so: a user typing in an open tab produces the same stale body, and the row does not record WHY the op-log is ahead. Carried by every door that serialises `models.Item`, and by the hand-built ones too — the playbook `run` response, bootstrap convention and bodies-mode include payloads, the exported artifact's `provenance` block, and a line above the body in the MCP item resource. The CLI prints it to **stderr** (`pad item show --format markdown`, `pad playbook show`, `pad playbook run`), like the write warnings — except `pad item show`'s default TABLE output, which since TASK-3132 opens with it on **stdout**; markdown stays stderr because its stdout is the body verbatim for `update --stdin` + - **READ responses may carry `content_state`** (BUG-3000 / BUG-3033) — the read-side counterpart to `warnings.content_outcome` above, and it takes the same one value, `applied_pending_flush`. A write warning says what a REQUEST did; this says what the ROW is: the item's op-log holds CONTENT-BEARING updates above `items.content_flushed_op_log_id`, so the body being served is BEHIND the live collaborative document. Since BUG-3124 rows that provably cannot change the document — y-protocols SyncStep1 frames, empty updates, and byte-identical re-sends of an earlier row (a SyncStep2 and an update differing only in their subtype byte count as identical since BUG-3136, which is what an open tab's answer to a joining tab is) — are persisted but marked `content_bearing = false` and not counted; they used to keep an item "pending" forever after its tab closed (measured: 470 pending items → 189 on the live DB). The classifier is envelope-only (no Yjs parse) and strict: a frame that does not parse exactly stays content-bearing. Additive and `omitempty`, and emitted only where a real body is — a summary or metadata projection that serves no content never claims its absent body is stale. The window is **unbounded**: nothing server-side moves that content into `items.content` (the op-log GC's flush-coverage guard deliberately RETAINS unflushed rows rather than flushing them), so the row catches up only when a browser tab next opens the item, which may never happen. Opening it is now enough even when nothing needs flushing (BUG-3124 unit B): a caught-up tab whose document still renders to the stored body calls `POST /workspaces/{ws}/items/{slug}/collab-watermark {op_log_cursor, content_sha256}`, and the server advances the flush watermark iff `cursor == MAX(op-log id)` and the sha256 matches `items.content`, atomically, writing no content, version, `seq` or `updated_at` — before this, a view that changed nothing was deduped and left the item "pending" forever. Web-client only; no CLI/MCP surface. The content is not lost — the op-log is the durability layer — but the marker is a signal to RE-READ LATER, never to re-send. The predicate is broader than "an API write is pending flush" and deliberately so: a user typing in an open tab produces the same stale body, and the row does not record WHY the op-log is ahead. Carried by every door that serialises `models.Item`, and by the hand-built ones too — the playbook `run` response, bootstrap convention and bodies-mode include payloads, the exported artifact's `provenance` block, and a line above the body in the MCP item resource. The CLI prints it to **stderr** (`pad item show --format markdown`, `pad playbook show`, `pad playbook run`), like the write warnings — except `pad item show`'s default TABLE output, which since TASK-3132 opens with it on **stdout**; markdown stays stderr because its stdout is the body verbatim for `update --stdin` - **A content write carrying a version token is REFUSED while a tab holds unflushed edits** (BUG-3133): 409 `content_pending_flush`, lifted by `overwrite_pending_edits: true`. The token guards the row, and those edits live only in the op-log until a tab flushes, so re-reading does not clear it. A tokenless content write still replaces them; with no tab open that deletes them from the op-log, and the response names how many in `warnings.pruned_pending_edits` (additive, omitempty; the CLI prints it to stderr) - **Write responses may also carry `warnings.dropped_fields`** (TASK-2878, widened by BUG-3079) — schema-declared keys the write DISCARDED. The general case is an injected schema DEFAULT that fails the same `validateFieldType` a caller-supplied value takes: it used to be assigned and skipped past that check, so the SAME BYTES were refused when supplied and stored when injected, decided only by who put them there — a `status` retyped to `multi_select` whose scalar default survived answered 400 to `{"status":"open"}` and 201 to `{}`, storing `{"status":"open"}`. It is now dropped and named here. The relation case keeps its own later pass, because "is this a string" and "does this string name a live, visible item" are different questions and only the first is answerable in the DB-free validator. Dropped rather than refused because nobody in the request typed it — EXCEPT on a `required` field, where dropping leaves it absent and the write is refused as required, with a message naming the default as the cause. Additive and `omitempty` - `POST /workspaces/{ws}/items/{slug}/copy/preflight` — cross-workspace copy dry run: what would carry / drop / need a value, plus the full warning set. Read-only and safe to call repeatedly (PLAN-2357) diff --git a/internal/store/bug3136_step2_twin_test.go b/internal/store/bug3136_step2_twin_test.go new file mode 100644 index 000000000..36d54555c --- /dev/null +++ b/internal/store/bug3136_step2_twin_test.go @@ -0,0 +1,192 @@ +package store_test + +import ( + "os" + "strings" + "testing" + + "github.com/PerpetualSoftware/pad/internal/models" +) + +// BUG-3136: an open tab answers a joining tab's SyncStep1 with a SyncStep2 +// carrying its full state, and the relay persists that answer. Its payload is +// byte-identical to the seed update the item already holds; only the subtype +// byte differs (01 vs 02), so the whole-frame twin check missed it and the item +// read pending after every first join. +// +// Both frames are REAL: rows 2 and 18 of BUG-3134's measurement instance (a +// 5-line doc, headless Chromium; row 2 is the lazy seed, row 18 the incumbent's +// answer to the first joiner). They are literals, not derived from each other, +// so the test cannot share an encoding mistake with the code under test. +var ( + probeSeedUpdate = mustDecode("0002BD020112E0E5C8B3080007010764656661756C74030768656164696E670700E0E5C8B30800060400E0E5C8B30801" + + "0550726F62652800E0E5C8B30800056C6576656C017D0187E0E5C8B3080003097061726167726170680700E0E5C8B308" + + "08060400E0E5C8B308092D4120706172616772617068206F6620626F6479207465787420666F7220746865206D656173" + + "7572656D656E742E87E0E5C8B30808030A62756C6C65744C6973740700E0E5C8B3083703086C6973744974656D0700E0" + + "E5C8B3083803097061726167726170680700E0E5C8B30839060400E0E5C8B3083A036F6E6587E0E5C8B3083803086C69" + + "73744974656D0700E0E5C8B3083E03097061726167726170680700E0E5C8B3083F060400E0E5C8B308400374776F2800" + + "E0E5C8B30837057469676874017887E0E5C8B30837030970617261677261706800") + probeStep2Answer = mustDecode("0001BD020112E0E5C8B3080007010764656661756C74030768656164696E670700E0E5C8B30800060400E0E5C8B30801" + + "0550726F62652800E0E5C8B30800056C6576656C017D0187E0E5C8B3080003097061726167726170680700E0E5C8B308" + + "08060400E0E5C8B308092D4120706172616772617068206F6620626F6479207465787420666F7220746865206D656173" + + "7572656D656E742E87E0E5C8B30808030A62756C6C65744C6973740700E0E5C8B3083703086C6973744974656D0700E0" + + "E5C8B3083803097061726167726170680700E0E5C8B30839060400E0E5C8B3083A036F6E6587E0E5C8B3083803086C69" + + "73744974656D0700E0E5C8B3083E03097061726167726170680700E0E5C8B3083F060400E0E5C8B308400374776F2800" + + "E0E5C8B30837057469676874017887E0E5C8B30837030970617261677261706800") +) + +func TestStep2AnswerDefersToItsUpdateTwin(t *testing.T) { + for _, b := range contentBackends() { + t.Run(b.name, func(t *testing.T) { + s := b.open(t) + _, _, item := seedStaleItem(t, s) + seed := appendFrame(t, s, item.ID, probeSeedUpdate) + if err := s.SetItemContentFlushedOpLogIDForTesting(item.ID, seed); err != nil { + t.Fatal(err) + } + // PREMISE: the flushed seed alone reads clean. + if got := contentState(t, s, item.ID); got != "" { + t.Fatalf("premise: a flushed seed must read clean; got %q", got) + } + appendFrame(t, s, item.ID, probeStep2Answer) + if got := contentState(t, s, item.ID); got != "" { + t.Fatalf("a step2 carrying the seed's exact payload changes nothing, so the item must stay clean; got %q", got) + } + }) + } +} + +// The equivalence runs both ways: an update whose payload an earlier step2 +// already carried is equally a no-op. +func TestUpdateDefersToItsStep2Twin(t *testing.T) { + for _, b := range contentBackends() { + t.Run(b.name, func(t *testing.T) { + s := b.open(t) + _, _, item := seedStaleItem(t, s) + first := appendFrame(t, s, item.ID, probeStep2Answer) + if err := s.SetItemContentFlushedOpLogIDForTesting(item.ID, first); err != nil { + t.Fatal(err) + } + appendFrame(t, s, item.ID, probeSeedUpdate) + if got := contentState(t, s, item.ID); got != "" { + t.Fatalf("an update repeating a flushed step2's payload must read clean; got %q", got) + } + }) + } +} + +// Control: a step2 whose payload differs from every earlier row is content, and +// the subtype rule must not swallow it. +func TestStep2WithNewPayloadStaysContentBearing(t *testing.T) { + for _, b := range contentBackends() { + t.Run(b.name, func(t *testing.T) { + s := b.open(t) + _, _, item := seedStaleItem(t, s) + seed := appendFrame(t, s, item.ID, probeSeedUpdate) + if err := s.SetItemContentFlushedOpLogIDForTesting(item.ID, seed); err != nil { + t.Fatal(err) + } + other := append([]byte(nil), probeStep2Answer...) + other[len(other)-1] ^= 0x01 + appendFrame(t, s, item.ID, other) + if got := contentState(t, s, item.ID); got != models.ContentOutcomeAppliedPendingFlush { + t.Fatalf("a step2 with a payload no earlier row carries must read pending; got %q", got) + } + }) + } +} + +// Strictness: a frame that does not parse exactly gets no subtype twin, even +// when an earlier row is its byte-for-byte subtype swap. Here the length prefix +// claims 5 bytes and 2 follow. +func TestMalformedFrameGetsNoSubtypeTwin(t *testing.T) { + for _, b := range contentBackends() { + t.Run(b.name, func(t *testing.T) { + s := b.open(t) + _, _, item := seedStaleItem(t, s) + first := appendFrame(t, s, item.ID, []byte{0x00, 0x02, 0x05, 0xAA, 0xBB}) + if err := s.SetItemContentFlushedOpLogIDForTesting(item.ID, first); err != nil { + t.Fatal(err) + } + appendFrame(t, s, item.ID, []byte{0x00, 0x01, 0x05, 0xAA, 0xBB}) + if got := contentState(t, s, item.ID); got != models.ContentOutcomeAppliedPendingFlush { + t.Fatalf("a malformed frame must stay content-bearing; got %q", got) + } + }) + } +} + +// Rows classified under migration 091's rule keep that verdict until +// something re-examines them. Migration 093 re-queues them; the startup +// backfill then applies the twin rule. The counterfactual leg shows the +// migration is what does it: without it the backfill has nothing to examine. +func TestMigration093RequeuesStep2RowsForTheBackfill(t *testing.T) { + for _, b := range contentBackends() { + t.Run(b.name, func(t *testing.T) { + s := b.open(t) + path := "migrations/093_yjs_step2_twin_reclassify.sql" + if b.name == "Postgres" { + path = "pgmigrations/070_yjs_step2_twin_reclassify.sql" + } + sqlText, err := os.ReadFile(path) + if err != nil { + t.Fatal(err) + } + _, _, item := seedStaleItem(t, s) + // A content-bearing row that is NOT a step2/update frame: 093 must + // leave it alone, so the count below catches a migration that drops + // its subtype predicate (codex round 1, P3). + appendFrame(t, s, item.ID, []byte{0x07, 0x01, 0x02}) + seed := appendFrame(t, s, item.ID, probeSeedUpdate) + answer := appendFrame(t, s, item.ID, probeStep2Answer) + if err := s.SetItemContentFlushedOpLogIDForTesting(item.ID, seed); err != nil { + t.Fatal(err) + } + // Reproduce the pre-BUG-3136 verdict on the answer row: classified + // (hash set) and content-bearing. + if _, err := s.DB().Exec(rebind(b.name, `UPDATE item_yjs_updates SET content_bearing = `+trueLit(b.name)+` WHERE id = ?`), answer); err != nil { + t.Fatal(err) + } + if got := contentState(t, s, item.ID); got != models.ContentOutcomeAppliedPendingFlush { + t.Fatalf("premise: the old verdict must read pending; got %q", got) + } + + // Counterfactual: the backfill alone does not revisit a classified row. + if res, err := s.BackfillYjsContentBearing(); err != nil || res.RowsClassified != 0 { + t.Fatalf("premise: without 093 the backfill must classify nothing; got %+v, %v", res, err) + } + + if _, err := s.DB().Exec(string(sqlText)); err != nil { + t.Fatalf("migration: %v", err) + } + res, err := s.BackfillYjsContentBearing() + if err != nil { + t.Fatal(err) + } + // 093 re-queues BOTH bearing step2/update rows: the seed + // (re-examined, still content: nothing earlier carries it) and the + // answer (cleared by its twin). The non-sync row is not re-queued. + if res.RowsClassified != 2 || res.RowsNonContent != 1 { + t.Fatalf("want 2 re-examined and 1 cleared; got %+v", res) + } + if got := contentState(t, s, item.ID); got != "" { + t.Fatalf("after 093 and the backfill the item must read clean; got %q", got) + } + }) + } +} + +// rebind turns the single ? placeholder these tests use into Postgres's $1. +func rebind(backend, q string) string { + if backend == "Postgres" { + return strings.Replace(q, "?", "$1", 1) + } + return q +} + +func trueLit(backend string) string { + if backend == "Postgres" { + return "TRUE" + } + return "1" +} diff --git a/internal/store/migrations/093_yjs_step2_twin_reclassify.sql b/internal/store/migrations/093_yjs_step2_twin_reclassify.sql new file mode 100644 index 000000000..dfdee08c0 --- /dev/null +++ b/internal/store/migrations/093_yjs_step2_twin_reclassify.sql @@ -0,0 +1,18 @@ +-- Migration 093: re-queue step2/update op-log rows for classification (BUG-3136). +-- +-- Migration 091's classifier treated a SyncStep2 and an update carrying the +-- same payload as different frames, so an open tab's step2 answer to a joining +-- tab stayed content-bearing and held the item "pending" although it carried +-- the same bytes as the seed update. The classifier now also matches that +-- subtype twin. Rows already classified keep their old verdict until they are +-- re-examined, so this clears content_hash on every content-bearing step2 and +-- update row, and the startup backfill (BackfillYjsContentBearing) reclassifies +-- them in id order under the new rule. +-- +-- Only content-bearing rows are re-queued: the new rule can only turn a +-- bearing row non-bearing, never the reverse. content_bearing itself is left +-- at 1 until the backfill decides, which is the safe direction. +UPDATE item_yjs_updates + SET content_hash = NULL + WHERE content_bearing = 1 + AND substr(update_data, 1, 2) IN (x'0001', x'0002'); diff --git a/internal/store/pgmigrations/070_yjs_step2_twin_reclassify.sql b/internal/store/pgmigrations/070_yjs_step2_twin_reclassify.sql new file mode 100644 index 000000000..ce738f341 --- /dev/null +++ b/internal/store/pgmigrations/070_yjs_step2_twin_reclassify.sql @@ -0,0 +1,6 @@ +-- Migration 070: re-queue step2/update op-log rows for classification (BUG-3136). +-- Postgres twin of SQLite migration 093; see that file for the rationale. +UPDATE item_yjs_updates + SET content_hash = NULL + WHERE content_bearing + AND substring(update_data from 1 for 2) IN ('\x0001'::bytea, '\x0002'::bytea); diff --git a/internal/store/yjs_content_bearing.go b/internal/store/yjs_content_bearing.go index 4a927d1fa..531ea55ab 100644 --- a/internal/store/yjs_content_bearing.go +++ b/internal/store/yjs_content_bearing.go @@ -25,6 +25,11 @@ import ( // 3. It is byte-identical to a row already persisted for the same item. Yjs // updates are idempotent, so applying the same bytes again changes nothing; // the earlier copy is what carries the content, and it is counted on its own. +// A SyncStep2 and an update count as identical when their frames differ ONLY +// in that subtype byte (BUG-3136): y-protocols applies both payloads through +// the same readUpdate, so the same payload bytes have the same effect under +// either envelope. This is what catches an open tab's step2 answer to a +// joining tab, which carries the same full state as the seed update. // // ERROR DIRECTION. content_state is trusted by `pad item edit`'s refusal // (BUG-3035) and by the SQLite→Postgres migration gate, which drops the op-log. @@ -94,18 +99,61 @@ func yjsFrameIsEnvelopeNonContent(data []byte) bool { } // yjsFrameHash is the content_hash column value: the sha256 of the WHOLE frame, -// envelope included, so a SyncStep2 and an update carrying the same payload are -// never treated as one another. +// envelope included. The step2/update equivalence of fact (3) is NOT folded into +// the hash; yjsIdenticalEarlierRowQ looks the subtype twin up separately, so the +// column keeps one meaning for rows written before and after BUG-3136. func yjsFrameHash(data []byte) string { sum := sha256.Sum256(data) return hex.EncodeToString(sum[:]) } +// yjsSyncSubtypeTwin returns data with its sync subtype swapped between +// SyncStep2 and update, for fact (3)'s envelope equivalence. ok is false for any +// frame that is not EXACTLY one well-formed step2/update message (the same strict +// parse as yjsFrameIsEnvelopeNonContent), so a frame this file does not +// understand never gains a twin. Both codes and the message type are single-byte +// varuints, so the swap is one byte at index 1. +func yjsSyncSubtypeTwin(data []byte) ([]byte, bool) { + msgType, pos, ok := readVarUint(data, 0) + if !ok || msgType != yFrameSync || pos != 1 { + return nil, false + } + subtype, pos, ok := readVarUint(data, pos) + if !ok || pos != 2 || (subtype != ySyncStep2 && subtype != ySyncUpdate) { + return nil, false + } + n, pos, ok := readVarUint(data, pos) + if !ok || uint64(len(data)-pos) != n { + return nil, false + } + twin := append([]byte(nil), data...) + if subtype == ySyncStep2 { + twin[1] = ySyncUpdate + } else { + twin[1] = ySyncStep2 + } + return twin, true +} + // yjsIdenticalEarlierRowQ reports whether the item's op-log already holds a -// frame byte-identical to data, below beforeID when beforeID > 0. The hash -// narrows the search through idx_yjs_updates_item_hash; the byte compare is what -// decides, so a hash collision could only ever leave a row content-bearing. +// frame byte-identical to data, or to its step2/update subtype twin, below +// beforeID when beforeID > 0. The hash narrows the search through +// idx_yjs_updates_item_hash; the byte compare is what decides, so a hash +// collision could only ever leave a row content-bearing. func (s *Store) yjsIdenticalEarlierRowQ(q Queryer, itemID string, data []byte, hash string, beforeID int64) (bool, error) { + dup, err := s.yjsExactEarlierRowQ(q, itemID, data, hash, beforeID) + if err != nil || dup { + return dup, err + } + twin, ok := yjsSyncSubtypeTwin(data) + if !ok { + return false, nil + } + return s.yjsExactEarlierRowQ(q, itemID, twin, yjsFrameHash(twin), beforeID) +} + +// yjsExactEarlierRowQ is the whole-frame lookup behind yjsIdenticalEarlierRowQ. +func (s *Store) yjsExactEarlierRowQ(q Queryer, itemID string, data []byte, hash string, beforeID int64) (bool, error) { query := `SELECT 1 FROM item_yjs_updates WHERE item_id = ? AND content_hash = ? AND update_data = ?` args := []interface{}{itemID, hash, data} @@ -135,8 +183,9 @@ type BackfillYjsContentBearingResult struct { // yjsBackfillBatch bounds one transaction of the backfill. const yjsBackfillBatch = 500 -// BackfillYjsContentBearing classifies op-log rows written before migration 091 -// (content_hash IS NULL). Called from server startup after migrations. +// BackfillYjsContentBearing classifies every op-log row whose content_hash IS +// NULL: rows written before migration 091, and the step2/update rows migration +// 093 re-queued (BUG-3136). Called from server startup after migrations. // // No completion marker, deliberately, unlike BackfillRelationLinks: here the // progress marker is PER ROW. content_hash IS NULL is exactly "not yet