oficina / docs Public

Task 5b fix round: pin the refused row, and warn when a replay re-seeds

Two review findings.

The tests did not pin the property the brief called the worst outcome:
that the row the cap refuses is re-applied rather than dropped. The
distinct fixture sat at core.MaxRetainedUpdates+40, but the refused row
is core.MaxRetainedUpdates+1 — an ordinary duplicate, and Yjs applies a
duplicate idempotently, so a re-seed that discarded the refused row and
continued rendered identically and passed all four tests. The fixture
now sits on the refused row itself, which pins both properties at once:
the replay continued past the cap, and the row it refused survived.
Verified by making the re-seed drop that row and watching all four fail.

The writes test also now reads the document back, rather than asserting
only that the write was accepted — a write on top of a lossy replay
persists that loss into the snapshot ApplyUpdate takes. It was the one
test the deliberate drop still slipped past.

And replay now logs at Warn each time it re-seeds, with doc_id and seq.
I had argued for silence because the next write repairs it; that assumes
a write arrives. Reads write nothing (D3), so a finished document that
is only ever read again — a large share of what one ABI bump invalidates
at once — re-seeds on every read forever, with latency as the only
evidence. Warn rather than Error because the document is correct and
merely slower, which is the distinction from the two Error lines beside
it, both of which mean a snapshot is unusable.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>

Paul Campbell pushed by paul@keymail.dev 1 month ago bdb7f7c5c2b7c56ec3075902881ba9c322abedbb parent b4d2ed3

2 files changed, +56 −10

internal/docs/snapshots_test.go +33 −10
internal/docs/store.go +23 −0

diff --git a/internal/docs/snapshots_test.go b/internal/docs/snapshots_test.go

index 8547c58..be2164e 100644

--- a/internal/docs/snapshots_test.go

+++ b/internal/docs/snapshots_test.go

@@ -667,12 +667,24 @@ func seedLongLog(t *testing.T, app *App, doc *Document, total int, distinct map[

const pastTheCapMarker = "BBB"

// longLogDistinctRows is the shape every test below seeds: a log past

-// core.MaxRetainedUpdates whose one distinct update sits PAST the cap,

-// among rows only a replay that carries on beyond core.ErrUpdateLogFull

-// ever applies. That placement is what makes "still reads" mean "reads

-// the whole document" rather than "reads its first 4096 rows" — a

-// replay that stopped at the cap and returned what it had would render

-// without pastTheCapMarker and fail.

+// core.MaxRetainedUpdates whose one distinct update sits at seq

+// core.MaxRetainedUpdates+1 — the row a replay's first handle REFUSES

+// with core.ErrUpdateLogFull, having already retained the 4096 before

+// it. That seq, and not a later one, is the whole point of the

+// placement, because it pins two properties with one assertion:

+//

+// - the replay carried on past the cap at all, rather than stopping

+// there and returning what it had; and

+// - the refused row was re-applied into the re-seeded handle rather

+// than dropped.

+//

+// The second needs this exact seq. Every other row here is validUpdate's

+// bytes, and Yjs applies a duplicate update idempotently, so dropping

+// any ordinary row changes nothing anyone can observe: a re-seed that

+// discarded the refused row and continued would render identically, and

+// a fixture parked at, say, +40 would let that variant pass. With the

+// fixture ON the refused row, dropping it loses content nothing else in

+// the log holds, and every assertion below notices.

// One distinct fixture, not several. The fragment fixtures are each

// generated from their own yjs document, and their struct ids overlap,

@@ -682,14 +694,14 @@ const pastTheCapMarker = "BBB"

func longLogDistinctRows(t *testing.T) (total int, distinct map[int][]byte) {

t.Helper()

return core.MaxRetainedUpdates + 50, map[int][]byte{

- core.MaxRetainedUpdates + 40: ReadFragmentFixture(t, "concurrent"),

+ core.MaxRetainedUpdates + 1: ReadFragmentFixture(t, "concurrent"),

}

// assertHoldsTheWholeLog fails unless html holds both ends of a log

// seeded by seedLongLog with longLogDistinctRows' placement: the

-// ordinary rows' own paragraphs, and pastTheCapMarker from the row

-// beyond core.MaxRetainedUpdates.

+// ordinary rows' own paragraphs, and pastTheCapMarker from the row the

+// first handle refused with core.ErrUpdateLogFull.

// It first renders the ordinary update on its own and requires that

// NOT to contain the marker. Without that, a fixture whose content the

@@ -715,7 +727,7 @@ func assertHoldsTheWholeLog(t *testing.T, app *App, doc *Document, html string)

// its only snapshot goes away — a corrupt row, or the first ABI bump,

// which newestSnapshot's exact-match filter invalidates every snapshot

// with at once — replay runs the whole log into one handle, meets

-// ErrUpdateLogFull at row 4096 and returns an error. Text, HTML and

+// ErrUpdateLogFull at row 4097 and returns an error. Text, HTML and

// JSON all go through replay, so such a document is not slow, it is

// unreadable.

func TestALongLogWithNoUsableSnapshotStillReads(t *testing.T) {

@@ -776,6 +788,17 @@ func TestALongLogWithNoUsableSnapshotStillAcceptsWrites(t *testing.T) {

if want := int64(total + 1); seq != want {

t.Errorf("ApplyUpdate wrote seq %d, want %d", seq, want)

}

+ // Accepting a write is not enough on its own: a write that went

+ // through on top of a replay that had quietly lost the row the cap

+ // refused would persist that loss into the snapshot ApplyUpdate

+ // takes above. So read the document back and require the whole log

+ // to still be in it.

+ html, err := app.Store().HTML(ctx, doc)

+ if err != nil {

+ t.Fatalf("HTML after the write: %v", err)

+ }

+ assertHoldsTheWholeLog(t, app, doc, string(html))

}

// The ABI-bump case, spelled out because it is the one that will

diff --git a/internal/docs/store.go b/internal/docs/store.go

index f980cde..a091d8b 100644

--- a/internal/docs/store.go

+++ b/internal/docs/store.go

@@ -447,6 +447,29 @@ func (s *Store) replay(ctx context.Context, doc *Document) (h *core.Handle, repl

// first statement and returns before it touches the guest,

// so this row is still owed and is applied below, into the

// fresh handle, exactly once.

+ //

+ // Warn, not Error, and not silence either. Not Error,

+ // because nothing is wrong with the document: it is

+ // complete, correct and merely slower to read (a re-seeding

+ // replay costs an apply per row, tens of milliseconds per

+ // thousand, against about a millisecond for snapshot plus a

+ // short tail), and this document's next write repairs it

+ // with an ordinary snapshot. That is precisely the

+ // distinction an operator needs — this line means "slow,

+ // self-healing", where the two Error lines above mean "a

+ // snapshot is unusable".

+ //

+ // And not silence, which is what this was at first, on the

+ // reasoning that the next write clears it. That reasoning

+ // assumes a write arrives. Reads write nothing (D3: Text,

+ // HTML and JSON discard both seqs), so a long document that

+ // is finished and only ever read again — a large share of

+ // what an ABI bump invalidates at once — re-seeds on every

+ // single read, forever, with latency as the only evidence.

+ // One line per read is the price of that not being invisible.

+ s.logger.Warn("docs: replay past the retained-update cap, re-seeding a fresh handle and continuing; slower until the next write writes a snapshot",

+ "doc_id", doc.ID, "seq", u.Seq)

h, err = s.reseedForReplay(ctx, doc, h, u.Seq)

if err != nil {

return nil, 0, 0, err