fix(store): a step2 answer carrying an update's exact payload is not content (BUG-3136) (#1422)

* fix(store): a step2 answer carrying an update's exact payload is not content (BUG-3136)

An open tab answers a joining tab's SyncStep1 with a SyncStep2 carrying its
full state, and the relay persists it. On an unedited doc that payload is
byte-identical to the seed update; only the subtype byte differs, so unit A's
whole-frame twin check missed it and the item read pending after every first
join. The twin lookup now also matches the frame with its subtype swapped
between step2 and update, for well-formed single-message frames only.
y-protocols applies both payloads through the same readUpdate, so identical
bytes have identical effect under either envelope.

Migration 092 (PG 069) re-queues content-bearing step2/update rows for the
startup backfill, which reclassifies them under the new rule. On a copy of
the live DB: 57,056 rows re-examined, 34 cleared, pending items 189 -> 178.
The 18 remaining bearing step2s above watermarks are edited docs whose merged
state no single earlier row equals; clearing those needs a Yjs parse.

Claude-Session: https://claude.ai/code/session_01X4uYKs5ZPF28eCWfm8VPvE

* test(store): pin that migration 092 leaves non-sync rows alone (BUG-3136, codex round 1 P3)

Claude-Session: https://claude.ai/code/session_01X4uYKs5ZPF28eCWfm8VPvE

* chore(store): renumber the step2 reclassify migration to 093 / PG 070 (BUG-3136)

#1421 landed first with 092 / 069.

Claude-Session: https://claude.ai/code/session_01X4uYKs5ZPF28eCWfm8VPvE
This commit is contained in:
xarmian
2026-09-22 01:27:03 -04:00
committed by GitHub
parent 3b7665a469
commit 6d6ac71908
5 changed files with 273 additions and 8 deletions
+1 -1
View File
@@ -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)
+192
View File
@@ -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"
}
@@ -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');
@@ -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);
+56 -7
View File
@@ -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